Problems with Z-Wave (devices can send updates, but does not accept commands)

Thorbjorn_Skistad · December 29, 2020, 11:00am

----The short story -----

Started with RPI3b+ with an older openhabian install.
Update from OH2.4 to 2.5 went well.
Update from OH2.5 to 3.0 went well.
Worked well (some cleanup of old plugins had to be done)
Fresh install on RPI4 with the latest release of OpenHabian
Backup OH3 on old box, restore on new.
Had to put Zwave stick on a USB 2.0 hub to make it work. (google helped!)
Zwave network ended up in a “read only” state - can recieve but not send data.
Putting the zwave stick back to the RPI3 -> working zwave!!
(strange… it’s running with the same data isn’t it?)

------The long story-----
I’ve updated my OpenHab 2.4 to 2.5, then ran the update to version 3. All well so far! (some old plugins had to be removed from conf files, but google provided a lot of help, so everything ended up working well)

I also wanted to get a new fresh start with the latest Openhabian (had an old one running on a RPI 3b+) I did a fresh install on a Raspberry PI 4b with the latest OpenHabian image (downloaded yesterday)

I then did a backup of OH3 which was updated from OH2.5 with openhab-cli backup , scp’d the backup over to the newly installed RPI4 and did openhab-cli restore .

Discovered that the Aeotec USB Zwave Stick Gen 5 will NOT work on a RPI4 unless it’s on a USB 2.0 hub, so connected a simple unpowered HUB to the RPI4 (no other devices connected to the HUB or the PI) - Now I could see my zwave network, and i get data from all the nodes, yaaay!

All seemed to work fine, until I discovered that the zwave network only sends data, it will not accept any changes sent by OH3, like turning on/off switches, or change the value of dimmers. Data is recieved, so I get updates from sensors and switches, but they will not accept any updates.

Status of THINGS says that it’s all OK, but somehow I’ve gotten to a state of a “read only” zwave network.

Lots of googling and I found the DEBUG and TRACE options to logging in OH.
When I set the zwave logging to DEBUG in karaf console and discovered these type of messages:
“NODE 5: sentData was not placed on stack.”

Then increased debugging to TRACE (these logs are hard to read, I’ve seen that Chris Jackson has some cool gui tool to make more sense of it, but I could not find it)

I moved my zwave stick back to the RPI3, (and booted it up again) - only to discover that zwave is working properly here (can turn stuff on and off, and set dimming levels)

I then checked that OH can write to the controller:
$ ll /dev/USBzwave
lrwxrwxrwx 1 root root 7 Dec 28 16:31 /dev/USBzwave -> ttyACM0

$ ll /dev/ttyACM0
crw-rw-rw- 1 root dialout 166, 0 Dec 29 2020 /dev/ttyACM0

and checked that the user “openhab” is a member of the group dialout, so I guess it has write access to the zwave stick.

My knowledge of how zwave works ends here… and google drowned me in all the stuff that did not help me much…

So this is the time to ask for help, hopefully some of you can make more sense of this trace.

------ output from openhab.log with zwave set to TRACE on the RPI4 (fresh install with backup restored) ------
2020-12-29 10:25:27.134 [TRACE] [sactionManager$ZWaveTransactionTimer] - Holdoff Timer triggered…
2020-12-29 10:25:27.134 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2020-12-29 10:25:27.135 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: listening == false, frequentlyListening == false, awake == false
2020-12-29 10:25:27.136 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 8: Node not awake!
2020-12-29 10:25:27.136 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: listening == false, frequentlyListening == false, awake == false
2020-12-29 10:25:27.137 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 11: Node not awake!
2020-12-29 10:25:27.137 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 16: listening == false, frequentlyListening == false, awake == false
2020-12-29 10:25:27.138 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 16: Node not awake!
2020-12-29 10:25:27.139 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 6: listening == false, frequentlyListening == false, awake == false
2020-12-29 10:25:27.139 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 6: Node not awake!
2020-12-29 10:25:27.140 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: listening == false, frequentlyListening == false, awake == false
2020-12-29 10:25:27.140 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 4: Node not awake!
2020-12-29 10:25:27.141 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: listening == false, frequentlyListening == false, awake == false
2020-12-29 10:25:27.141 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 19: Node not awake!
2020-12-29 10:25:27.142 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 15: listening == false, frequentlyListening == false, awake == false
2020-12-29 10:25:27.142 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 15: Node not awake!
2020-12-29 10:25:27.143 [TRACE] [ng.zwave.internal.protocol.ZWaveNode] - NODE 5: listening == true, frequentlyListening == false, awake == false
2020-12-29 10:25:27.144 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction from sendQueue
2020-12-29 10:25:27.144 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2020-12-29 10:25:27.145 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -16
2020-12-29 10:25:27.146 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 05 03 25 01 FF 25 EE F0
2020-12-29 10:25:27.147 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 0A 00 13 05 03 25 01 FF 25 EE F0
2020-12-29 10:25:27.147 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2020-12-29 10:25:27.148 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 215: Transaction Start type SendData
2020-12-29 10:25:27.149 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2020-12-29 10:25:27.149 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 215: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 238
2020-12-29 10:25:27.150 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2020-12-29 10:25:27.150 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06
2020-12-29 10:25:27.150 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: 0
2020-12-29 10:25:27.151 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2020-12-29 10:25:27.151 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-12-29 10:25:27.152 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2020-12-29 10:25:27.152 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Dec 29 10:25:29 CET 2020 - 2000ms
2020-12-29 10:25:27.153 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2020-12-29 10:25:27.153 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2020-12-29 10:25:27.154 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2020-12-29 10:25:27.154 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2020-12-29 10:25:27.155 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2020-12-29 10:25:27.155 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 00 E9
2020-12-29 10:25:27.156 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 215: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 238
2020-12-29 10:25:27.157 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2020-12-29 10:25:27.157 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 00 E9
2020-12-29 10:25:27.158 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Dec 29 10:25:29 CET 2020 - 1994ms
2020-12-29 10:25:27.158 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -23
2020-12-29 10:25:27.159 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2020-12-29 10:25:27.159 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2020-12-29 10:25:27.159 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding…
2020-12-29 10:25:27.159 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 00
2020-12-29 10:25:27.160 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2020-12-29 10:25:27.160 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2020-12-29 10:25:27.161 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Tue Dec 29 10:25:29 CET 2020 - 1992ms
2020-12-29 10:25:27.161 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2020-12-29 10:25:27.162 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=00
2020-12-29 10:25:27.163 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2020-12-29 10:25:27.163 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=00
2020-12-29 10:25:27.164 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 215: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 238
2020-12-29 10:25:27.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2020-12-29 10:25:27.165 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 215: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 238
2020-12-29 10:25:27.166 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 16 0A 60 0D 02 01 31 05 01 22 00 DB 55
2020-12-29 10:25:27.166 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=00
2020-12-29 10:25:27.167 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
2020-12-29 10:25:27.167 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 10 00 04 00 16 0A 60 0D 02 01 31 05 01 22 00 DB 55
2020-12-29 10:25:27.168 [TRACE] [l.serialmessage.SendDataMessageClass] - Handle Message Send Data Response
2020-12-29 10:25:27.168 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 85
2020-12-29 10:25:27.168 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: sentData was not placed on stack.
2020-12-29 10:25:27.169 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2020-12-29 10:25:27.169 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 215: Transaction CANCELLED
2020-12-29 10:25:27.169 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 215: TransactionAdvance ST: CANCELLED
2020-12-29 10:25:27.170 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 22: Message payload = 00 16 0A 60 0D 02 01 31 05 01 22 00 DB
2020-12-29 10:25:27.170 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 215: TransactionAdvance WT: null {}
2020-12-29 10:25:27.171 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2020-12-29 10:25:27.171 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 215: TransactionAdvance RX: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=00
2020-12-29 10:25:27.171 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 215: TransactionAdvance TO: CANCELLED
2020-12-29 10:25:27.172 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2020-12-29 10:25:27.172 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer started…
2020-12-29 10:25:27.172 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2020-12-29 10:25:27.173 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=22, callback=0, payload=00 16 0A 60 0D 02 01 31 05 01 22 00 DB
2020-12-29 10:25:27.173 [TRACE] [nal.protocol.ZWaveTransactionManager] - Holdoff Timer finishing in 249ms
2020-12-29 10:25:27.174 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2020-12-29 10:25:27.174 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-12-29 10:25:27.175 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: Retry count exceeded. Discarding message: TID 215: [CANCELLED] priority=Set, requiresResponse=true, callback: 238
2020-12-29 10:25:27.176 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: TID 215: Transaction completed
2020-12-29 10:25:27.176 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 5: notifyTransactionResponse TID:215 CANCELLED
2020-12-29 10:25:27.177 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2020-12-29 10:25:27.178 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2020-12-29 10:25:27.179 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=22, callback=0, payload=00 16 0A 60 0D 02 01 31 05 01 22 00 DB
2020-12-29 10:25:27.180 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
------ log end -----

Best regards
Thorbjørn Skistad

Thorbjorn_Skistad · December 29, 2020, 11:57am

Just for reference, here’s openhab.log with zwave binding log set to TRACE on the rpi3 (the old install, that was updated) - where zwave commands works.

12:53:34.863 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling…
12:53:34.880 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:controller:node5:switch_binary --> OFF [OnOffType]
12:53:34.885 [DEBUG] [ndclass.ZWaveBinarySwitchCommandClass] - NODE 5: Creating new message for application command SWITCH_BINARY_SET
12:53:34.889 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_SWITCH_BINARY
12:53:34.894 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured
12:53:34.898 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Adding to device queue
12:53:34.903 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Added 100 to queue - size 8
12:53:34.907 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
12:53:34.912 [DEBUG] [zwave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 05 03 25 01 00 25 39 D8
12:53:34.917 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - NODE 5: Sending REQUEST Message = 01 0A 00 13 05 03 25 01 00 25 39 D8
12:53:34.921 [DEBUG] [ding.zwave.handler.ZWaveSerialHandler] - Message SENT
12:53:34.924 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
12:53:34.926 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 100: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 57
12:53:34.929 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12:53:34.933 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling initialised at 86400 seconds - start in 1500 milliseconds.
12:53:34.937 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
12:53:34.936 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
12:53:34.947 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
12:53:34.948 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 100: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 57
12:53:34.955 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg: ACK
12:53:34.955 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 39 00 00 02 D0
12:53:34.959 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
12:53:34.962 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=57, payload=39 00 00 02
12:53:34.962 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 100: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 57
12:53:34.966 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
12:53:34.969 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 100: [WAIT_RESPONSE] priority=Set, requiresResponse=true, callback: 57
12:53:34.971 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01
12:53:34.974 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 5: sentData successfully placed on stack.
12:53:34.976 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - TID 100: Advanced to WAIT_REQUEST
12:53:34.978 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: TID 100: Transaction not completed
12:53:34.981 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=57, payload=39 00 00 02
12:53:34.984 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction TID 100: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 57
12:53:34.986 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
12:53:34.989 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Last transaction: TID 100: [WAIT_REQUEST] priority=Set, requiresResponse=true, callback: 57
12:53:34.991 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Checking TID 100: (Callback 57)
12:53:34.994 [DEBUG] [l.serialmessage.ZWaveCommandProcessor] - Callback match!
12:53:34.996 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Correlated to TID 100: callback 57
12:53:34.998 [DEBUG] [ave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=57, payload=39 00 00 02
12:53:35.001 [DEBUG] [ol.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 57, Status = Transmission complete and ACK received(0)
12:53:35.003 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
12:53:35.006 [DEBUG] [ve.internal.protocol.ZWaveTransaction] - TID 100: Transaction COMPLETED
12:53:35.008 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Response processed after 83ms
12:53:35.010 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: TID 100: Transaction completed
12:53:35.012 [DEBUG] [ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 00 04 00 05 03 20 03 00 D7
12:53:35.013 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: notifyTransactionResponse TID:100 DONE
12:53:35.017 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 03 20 03 00
12:53:35.019 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
12:53:35.022 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=5, callback=0, payload=00 05 03 20 03 00
12:53:35.025 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - lastTransaction null
12:53:35.027 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Application Command Request (ALIVE:DONE)
12:53:35.029 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: resetResendCount initComplete=true isDead=false
12:53:35.032 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: Incoming command class COMMAND_CLASS_BASIC, endpoint 0
12:53:35.034 [DEBUG] [ing.zwave.internal.protocol.ZWaveNode] - NODE 5: SECURITY NOT required on COMMAND_CLASS_BASIC
12:53:35.037 [DEBUG] [otocol.commandclass.ZWaveCommandClass] - NODE 5: Received COMMAND_CLASS_BASIC V1 BASIC_REPORT
12:53:35.039 [DEBUG] [l.commandclass.ZWaveBasicCommandClass] - NODE 5: Basic report, value = 0
12:53:35.041 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
12:53:35.044 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_BASIC, value=0
12:53:35.046 [DEBUG] [nding.zwave.handler.ZWaveThingHandler] - NODE 5: Updating channel state zwave:device:controller:node5:switch_binary to OFF [OnOffType]
12:53:35.049 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Commands processed 1.
12:53:35.053 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - NODE 5: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@1e654fb.
12:53:35.055 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
12:53:35.057 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
12:53:35.060 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
12:53:35.062 [DEBUG] [rnal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

Bruce_Osborne · December 29, 2020, 12:08pm

Why??? The binding documentation is clear only DEBUG level is needed for troubleshooting.

BTW, there is a helpful log viewer here.

Thorbjorn_Skistad · December 29, 2020, 12:57pm

I tried Debug first, but I did not get any helpful pointers, so tried Trace… no other reason.

Thanks for the log viewer, will try that right away!

Thorbjorn_Skistad · December 29, 2020, 1:11pm

[RX RES SendData 238 REJECTED BY CONTROLLER]

Hmmm… what can be the issue that causes the controller to reject packages on the new install, but not the old?

Some data that the backup/restore procedure did not copy??
Where are the controllers data kept?
Can I diff the files??, to figure out what’s missing on the new install?

Best regards
Thorbjørn

Bruce_Osborne · December 29, 2020, 1:42pm

Any devices securely included? The key is saved in the binding.

Thorbjorn_Skistad · December 29, 2020, 1:44pm

No, don’t use security (uses more power and doorlocks are a separate system from the rest of my home automation)

But, regardless of that, the security key was included with the backup/restore procedure. (or… at least the security key displayed in the GUI is the same, if it is different under the hood… I don’t know)

Thorbjorn_Skistad · December 29, 2020, 2:07pm

Hmm…I don’t understand what’s going on. All I’ve changed is debug/info loglevel for zwave from the karaf console (and several reboots, which I’ve done quite a few times now). Suddenly it started working on the RPI4 as well.

There’s no point in debugging something that works, even though I don’t understand one bit of it not working before. It’s the same aeotec stick I’ve been moving between the two raspberries.

Will do several more reboots to check that it keeps working.

Thanks for taking the time to help

Best regards
Thorbjørn

Thorbjorn_Skistad · December 29, 2020, 2:21pm

Several reboots later, and it still works!

The only thing I can think of I did differently is plugging the usb hub (with the zwave stick) to the lower of the two black ports on the RPI4. Can’t understand why that would make a difference though.

Sorry to all the others hoping to find some useful help in this thread later on… There isn’t a clear solution here. Waiting, reboots, turning zwave debuglogging on/off, and in time it just worked by itself… but no real solution for others having the same issue.

/Thorbjørn

Bruce_Osborne · December 29, 2020, 2:41pm

The Pi 4 has some USB2 ports in addition to USB3, I believe. Perhaps that is part of the puzzle.

Thorbjorn_Skistad · December 29, 2020, 2:52pm

I tried them all in the start (two black ports - USB2, two blue - USB3).
I ended up using the lower USB2 (black) port, with the USB2 hub plugged in there, and the Aeotec zwave stick plugged into the first port on the hub. (if that helps anyone later)

The stick apparently has some bad hardware design, not complying to the usb spec as it should, so a usb 2 hub masks that out from the rpi4 usb controller (found that in another thread on google, but can’t remember where at the moment). That bug caused the controller not to show up in lsusb. (which was the first issue I had to overcome, before I had the trouble of a “read only” controller… that apparently was a controller rejecting traffic. Why we will never figure out I’m afraid.

/thors

Bruce_Osborne · December 29, 2020, 2:54pm

They fixed that with a newer version stick. In the USB2 port you likely do not need the hub.