OH2 Z-Wave refactoring and testing... and SECURITY

[chris (Chris Jackson)]

@5iver

Another strange one…

Comments on this one…

• The holdoff doesn’t help you here - all 3 retries are rejected. According to the docs, this is caused by lack of available buffers in the controller. The idea behind the holdoff was to allow time for things to clear - here it hasn’t helped, so I wonder what is happening on your network…
• Same comment as earlier about the OFFLINE - it’s caused by the controller rejecting the messages, so we shouldn’t set the device OFFLINE. I’ll change this and I suspect it will really help the number of devices that you see are offline… Of course, it won’t fundamentally improve anything as the errors will still be there.
• If I don’t filter on node 22, I see other stuff happening - especially around 07:07:59 onward. There are node neighbour updates - I think I read that these cause a lot of network traffic and maybe it’s a bad idea to do this during initialisation…
• At this time (07:07:59) I see a node neighbour update for node 84, but we never sent it a request… We did request an update from node 88… I know we see quite a few corrupt frames on your system with nodes outside of the allowable range so maybe that explains this (it’s a guess…).
• The two no_ops sent at the end are because the first one was cancelled by the controller and it was resent (again, you can see this if you remove the filtering).

[chris (Chris Jackson)]

@5iver

this one is from a WADWAZ-1 door sensor.

This looks like the binding still thinks the device is awake, but I guess it has gone to sleep without telling anyone. During initialisation we try and keep the device awake to speed up the initialisation. I’ll have to have a think about this - maybe we can mark the device asleep if there are timeouts…

Thanks for the logs - a couple of things to look at, although I’m also a bit suspicious there’s more going on in your system than we can see, but I don’t know how to find out what at the moment.

[chris (Chris Jackson)]

@5iver please try this version.

I will be going out shortly but will be back in a few hours…

[5iver (Scott Rushworth)]

@chris

According to the docs, this is caused by lack of available buffers in the controller.

Is it possible to check the buffers through the serial API?

@chris

The idea behind the holdoff was to allow time for things to clear - here it hasn’t helped, so I wonder what is happening on your network…

You have the logs from a restart, so hopefully it’s all in there! Restarts are VERY congested. For small networks, checking all of the devices doesn’t seem to cause a problem, but it’s a heavy load for a big network to handle. I know (well… don’t care to know) that none of the devices have failed, changed, etc. I know you’ve explained this before… I can understand getting the state, but why go through the initialization each time the binding starts? Persistence can restore the state on startup, and a poll could be kicked off after a restart to refresh the states in case the system was down for a long while. Initializing 120 devices at once seems to be too much too fast. At least for my network! I doubt reworking the startup process is something that you’d want to do before merging to master, so maybe it could be addressed in the next refactoring? Maybe it’s as simple as an option to disable the initialization at startup?

@chris

@5iver please try this version.

At first this build seemed better, but I also restarted OH, where I only dropped the jar last time. At one point I noticed 24 dead nodes, so it does not seem much better. I think there’s something to the battery powered nodes being marked offline during wakeups.

There is a huge chunk of CANs in a small timeframe… 253 of them!

09:32:39.320		RX CAN
...
09:32:40.835		RX CAN

Is there still some of the old dead node check in the code? This looks like the controller was queried for the status of the node. Also, 6s goes by without a TX to the node after it woke up. Could it be sleeping again? Seems likely, since it does not respond and is then marked offline 50s after wakeup. Strange that it says it is asleep after almost 5min!

09:32:35.977	118	Node is AWAKE
09:32:41.996	118	TX REQ IsFailedNodeID Check if NODE 118 is failed
09:32:41.998		RX ACK
09:32:42.001	118	RX RES IsFailedNodeID NODE 118 is marked as FAILED by controller.
09:32:42.011	118	Stage advanced to REQUEST_NIF
09:32:42.078	118	TX REQ RequestNodeInfo
...
09:33:24.117	118	MESSAGE TIMEOUT
09:33:24.120	118	OFFLINE
...
09:37:05.955	118	RX REQ SendData 168 NO ACK after 6955ms
09:37:16.198	118	Node is ASLEEP

Similar here… 14s until request is sent (probably went back tp sleep), eventually marked offline, and then 4min after wakeup marked as asleep.

09:37:55.862	85	Node is AWAKE
09:38:10.604	85	TX REQ RequestNodeInfo
...
09:39:01.400	85	MESSAGE TIMEOUT
09:39:01.401	85	OFFLINE
...
09:41:53.886	85	RX REQ SendData 233 NO ACK after 6044ms
09:42:04.926	85	Node is ASLEEP

This looks like a pattern…

09:44:56.927	51	Node is AWAKE
09:45:21.754	51	TX REQ RequestNodeInfo
...
09:45:37.391	51	MESSAGE TIMEOUT
09:45:37.391	51	OFFLINE
...
09:47:54.925	51	RX REQ SendData 79 NO ACK after 6130ms
09:48:05.808	51	Node is ASLEEP

I sent you these logs.

[chris (Chris Jackson)]

@5iver

Is it possible to check the buffers through the serial API?

chris:

I don’t think so, but I’ll see if I can find anything.

@5iver

so hopefully it’s all in there!

I guess my point is not what we can see, but what we can’t… I have something in the pipeline, but I will discuss with you separately…

@5iver

but why go through the initialization each time the binding starts?

It doesn’t initialise eery time the binding starts. That’s the purpose of the XML - most of the initialisation data is persisted in the XML files, and fundamentally the only data we request on restart is the (so called) dynamic data - that’s all the stuff that can change state.

@5iver

Initializing 120 devices at once seems to be too much too fast.

The only time this will happen is if you remove the XML files.

@5iver

I doubt reworking the startup process is something that you’d want to do before merging to master

What do you suggest to rework? I’m not sure there’s anything much that can be done. We could not update the state I guess and just wait for devices to resend data when they like, but I’m sure people will complain about that as well. I think it’s wise to update the state .

@5iver

Maybe it’s as simple as an option to disable the initialization at startup?

As above - there is no initialisation on startup unless the XML file is removed.

@5iver

Is there still some of the old dead node check in the code?

Yes - the binding asks the controller if the device has failed. It doesn’t add any network traffic so it’s useful information. It could be removed, but I don’t think it will change anything.

@5iver

Also, 6s goes by without a TX to the node after it woke up.

What else is happening though? You can’t just look at a single device in isolation - if there are other transactions outstanding, then they will block the system. I see you sent me the log - if you look, you will see that there are other transactions in progress - it’s not that there is nothing happening If that’s what you are thinking?

@5iver

Similar here

Again though, what else is happening? You can’t just look at one node in isolation… It’s a busy time, and there’s a lot happening and there are a lot of queued transactions…

@5iver

There is a huge chunk of CANs in a small timeframe… 253 of them!

I need to add the holdoff into this as well…

[digitaldan (Dan Cunningham)]

Hi Chris, I just tried org.openhab.binding.zwave_2.4.0.201807071411.jar , which I think is the last jar posted and have a similar dead node issue that I had before. I have a clean log file for that. I’m now running zwave jar 2.3.0.201806262322 that i had been using previously and as soon as I get that log file I will post both back to your site.

[chris (Chris Jackson)]

@5iver to make it a little easier to see some of this I’ve updated the log viewer to add a new highlight filter. There’s now an extra set of checkboxes in the filter screen -:

Selecting one of these boxes will highlight packets from that node -:

It’s not 100% perfect - the Select All / Select None buttons act on all boxes, but I’ll look at this in the near future…

I’m looking at a way to try an elevate priority of battery nodes when they wake - one for tomorrow though…

[digitaldan (Dan Cunningham)]

Ok, the logs are submitted, I ran zwave_2.4.0.201807071411 first, then 2.3.0.201806262322 , then zwave_2.4.0.201807071411 again. I restarted OH between each run. Thanks!

[Pedals2Paddles (Matt)]

I was directed here when Googling why my Z-Wave door lock and two garage door openers aren’t working. I really am not in a position to read 3,168 replies so I will just ask:

• Does this work reliably and stable?
• I actually need to delete all my things in order to install this? Does that mean I will need rename them all when add them back again? This seems like a heavy lift.
• I downloaded the jar file linked in the OP. Where am I supposed to put it in the directory structure? Or does it run to execute something?
• Did I miss something obvious somewhere that said OpenHab stable does not support security enabled devices?? I feel like this is a pretty major thing to not have support for in stable, and would be obviously noted. But sometimes I overlook the obvious.

[sihui]

@Pedals2Paddles

Does this work reliably and stable?

For most of us: yes.

@Pedals2Paddles

I actually need to delete all my things in order to install this?

Yes. Just delete (not exclude!) and readd them, no need for renaming or relinking to channels or whatever.

@Pedals2Paddles

Where am I supposed to put it in the directory structure?

Look at the first couple of posts: you need to uninstall your current zwave binding an put the downloaded jar file into your /addons folder. You may need to install the serial transport dependency (for this you may also read some of the first posts).

@Pedals2Paddles

Did I miss something obvious somewhere that said OpenHab stable does not support security enabled devices??

The zwave stable binding and the zwave snapshot binding do not support secure devices yet. You need to install the zwave development/secure version of the zwave binding from this thread.

[5iver (Scott Rushworth)]

Using the last version, all of the devices became unresponsive, and it appears that none of the devices had completed initialization. They were definitely responding earlier. After an OH restart, the devices were responsive again.

2018-07-07 23:50:19.369 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 228: Command received zwave:device:07cb40a2:node228:switch_binary --> ON
2018-07-07 23:50:19.369 [DEBUG] [rotocol.commandclass.ZWaveBinarySwitchCommandClass] - NODE 228: Creating new message for application command SWITCH_BINARY_SET
2018-07-07 23:50:19.369 [DEBUG] [saction.ZWaveCommandClassTransactionPayloadBuilder] - At build null
2018-07-07 23:50:19.369 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 228: Encapsulating message, endpoint 0
2018-07-07 23:50:19.369 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 228: SECURITY NOT required on COMMAND_CLASS_SWITCH_BINARY
2018-07-07 23:50:19.369 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 228: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured
2018-07-07 23:50:19.369 [DEBUG] [rotocol.commandclass.ZWaveBinarySwitchCommandClass] - NODE 228: Creating new message for application command SWITCH_BINARY_GET
2018-07-07 23:50:19.369 [DEBUG] [saction.ZWaveCommandClassTransactionPayloadBuilder] - At build COMMAND_CLASS_SWITCH_BINARY
2018-07-07 23:50:19.369 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 228: Encapsulating message, endpoint 0
2018-07-07 23:50:19.369 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 228: SECURITY NOT required on COMMAND_CLASS_SWITCH_BINARY
2018-07-07 23:50:19.369 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 228: Command Class COMMAND_CLASS_SWITCH_BINARY is NOT required to be secured
2018-07-07 23:50:19.369 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 228: Adding to device queue
2018-07-07 23:50:19.369 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 228: Transaction already in queue - removing original
2018-07-07 23:50:19.369 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true
2018-07-07 23:50:19.369 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Holdoff Timer active - no send...
2018-07-07 23:50:19.369 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 228: Adding to device queue
2018-07-07 23:50:19.369 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 228: Transaction already in queue - removing original
2018-07-07 23:50:19.369 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true
2018-07-07 23:50:19.369 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Holdoff Timer active - no send...
2018-07-07 23:50:19.369 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 228: Polling intialised at 86400 seconds - start in 1500 milliseconds.
2018-07-07 23:50:20.308 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 67: WakeupTimerTask 2 Messages waiting, state UPDATE_NEIGHBORS
2018-07-07 23:50:20.870 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 228: Polling...
2018-07-07 23:50:20.870 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 228: Polling deferred until initialisation complete

Three hours after a restart and my devices are not responding again. Looks like commands are just being sent to the queue and…

2018-07-08 03:56:06.351 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff true
2018-07-08 03:56:06.351 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Holdoff Timer active - no send...

@chris

It doesn’t initialise eery time the binding starts. That’s the purpose of the XML - most of the initialisation data is persisted in the XML files, and fundamentally the only data we request on restart is the (so called) dynamic data - that’s all the stuff that can change state.

It gets confusing without terminology to distinguish between the initialization after inclusion and the initialization after startup. If it’s not initialization, what to call it?

@chris

Again though, what else is happening? You can’t just look at one node in isolation… It’s a busy time, and there’s a lot happening and there are a lot of queued transactions…

I completely understand, but I was trying to just point out that the delay in responding to the battery devices after a wakeup could explain them being marked as dead.

@chris

What do you suggest to rework? I’m not sure there’s anything much that can be done. We could not update the state I guess and just wait for devices to resend data when they like, but I’m sure people will complain about that as well. I think it’s wise to update the state .

I think something should be done with the amount of congestion after startup… some way to throttle it back. I have my wakeups set to one hour. I’ll try increasing this a bit to see if that might help. But currently, anything waking up after a startup is likely to be marked as dead and brought back to life again when it next wakes up. Prioritizing the communication for devices that sleep and are awake makes sense to me.

[dakkar]

hmmm is there any way, how to reset everything zwave related in openhab and start over from the beginning?

I have problems adding nodes, some are not updating they’re channels etc. I’d like to do a fresh start in order to be shure, the problem is not on my end.

simply removing the things and cling “hard reset controller” does not seem to be enough, as some nodes are rediscoverd by their old name/settings

Here a log snipplet of a failing inclusion:

2018-07-08 10:26:51.394 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not     running - nothing to do
2018-07-08 10:26:51.402 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Starting ZWave inclusion scan for zwave:serial_zstick:razberry1
2018-07-08 10:26:51.406 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 2
2018-07-08 10:26:51.410 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2018-07-08 10:26:51.413 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
2018-07-08 10:26:51.416 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:true.
2018-07-08 10:26:51.419 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
2018-07-08 10:26:51.423 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A C1 07 76 
2018-07-08 10:26:51.426 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A C1 07 76 
2018-07-08 10:26:51.431 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-08 10:26:51.433 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-08 10:26:51.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-08 10:26:51.437 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-08 10:26:51.438 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-08 10:26:51.438 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 07 01 00 00 B4 
2018-07-08 10:26:51.440 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-07-08 10:26:51.441 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-08 10:26:51.443 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
2018-07-08 10:26:51.456 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-08 10:26:51.459 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 15: Transaction Start type AddNodeToNetwork 
2018-07-08 10:26:51.487 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=7, payload=07 01 00 00 
2018-07-08 10:26:51.490 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=7, payload=07 01 00 00 
2018-07-08 10:26:51.492 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=7, payload=07 01 00 00 
2018-07-08 10:26:51.495 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 15: [WAIT_REQUEST] requiresResponse=true callback: 7
2018-07-08 10:26:51.497 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-08 10:26:51.499 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 15: [WAIT_REQUEST] requiresResponse=true callback: 7
2018-07-08 10:26:51.501 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 15: (Callback 7)
2018-07-08 10:26:51.503 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-07-08 10:26:51.505 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 15: callback 7
2018-07-08 10:26:51.507 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=7, payload=07 01 00 00 
2018-07-08 10:26:51.510 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
2018-07-08 10:26:51.514 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart

==> /var/log/openhab2/events.log <==
2018-07-08 10:26:51.514 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@c706a4

==> /var/log/openhab2/openhab.log <==
2018-07-08 10:26:51.516 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 15: Transaction COMPLETED
2018-07-08 10:26:51.520 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 61ms
2018-07-08 10:26:51.522 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 15: Transaction completed
2018-07-08 10:26:51.524 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:15 DONE
2018-07-08 10:26:51.528 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-08 10:26:51.530 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
2018-07-08 10:27:21.402 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeStart
2018-07-08 10:27:21.406 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2018-07-08 10:27:21.409 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
2018-07-08 10:27:21.414 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 08 BD 
2018-07-08 10:27:21.418 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 08 BD 
2018-07-08 10:27:21.424 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-08 10:27:21.426 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-08 10:27:21.430 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-08 10:27:21.434 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-08 10:27:21.436 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2018-07-08 10:27:21.439 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-07-08 10:27:21.441 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-08 10:27:21.443 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
2018-07-08 10:27:21.447 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-08 10:27:21.450 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 16: Transaction Start type AddNodeToNetwork 
2018-07-08 10:27:21.532 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 08 06 00 00 BC 
2018-07-08 10:27:21.568 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=8, payload=08 06 00 00 
2018-07-08 10:27:21.573 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=8, payload=08 06 00 00 
2018-07-08 10:27:21.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=8, payload=08 06 00 00 
2018-07-08 10:27:21.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 16: [WAIT_REQUEST] requiresResponse=true callback: 8
2018-07-08 10:27:21.590 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-07-08 10:27:21.595 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 16: [WAIT_REQUEST] requiresResponse=true callback: 8
2018-07-08 10:27:21.601 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 16: (Callback 8)
2018-07-08 10:27:21.606 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2018-07-08 10:27:21.612 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 16: callback 8
2018-07-08 10:27:21.618 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=8, payload=08 06 00 00 
2018-07-08 10:27:21.624 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
2018-07-08 10:27:21.629 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeDone, new event IncludeDone
2018-07-08 10:27:21.635 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2018-07-08 10:27:21.640 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-08 10:27:21.646 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2018-07-08 10:27:21.652 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2018-07-08 10:27:21.657 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 16: Advanced to DONE
2018-07-08 10:27:21.663 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 213ms
2018-07-08 10:27:21.668 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 16: Transaction completed
2018-07-08 10:27:21.673 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:16 DONE
2018-07-08 10:27:21.681 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-08 10:27:21.686 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false
2018-07-08 10:27:21.692 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5 
2018-07-08 10:27:21.698 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5 
2018-07-08 10:27:21.705 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-07-08 10:27:21.710 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-08 10:27:21.714 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-08 10:27:21.726 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-07-08 10:27:21.729 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 17: Transaction Start type AddNodeToNetwork 
2018-07-08 10:27:21.731 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-07-08 10:27:21.734 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 17: [WAIT_REQUEST] requiresResponse=true callback: 0
2018-07-08 10:27:21.736 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-07-08 10:27:21.738 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-07-08 10:27:21.740 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false
2018-07-08 10:27:26.732 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 17: Timeout at state WAIT_REQUEST. 3 retries remaining.
2018-07-08 10:27:26.736 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 17: Transaction is current transaction, so clearing!!!!!
2018-07-08 10:27:26.743 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 17: Transaction CANCELLED
2018-07-08 10:27:26.747 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:17 CANCELLED
2018-07-08 10:27:26.754 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false

[chris (Chris Jackson)]

@5iver

If it’s not initialization, what to call it?

Well, it’s still an initialisation - but it’s much more limited. If you like we can call it partial initialisation if you like. I was just responding to the way you wrote your mail which talked about “why go through initialisation each time the binding starts”. There is ALWAYS some initialisation, but most of the time it’s minimal if we already have the data.

@5iver

some way to throttle it back

What do you suggest? Currently, there is a queue, and only 1 transaction is processed at a time - what other throttling do you suggest?

@5iver

Prioritizing the communication for devices that sleep and are awake makes sense to me.

As I said last night, this is what I’m looking at doing -:

@chris

I’m looking at a way to try an elevate priority of battery nodes when they wake

@5iver

Three hours after a restart and my devices are not responding again

Can you provide a log please? Preferably spanning the area where the hold-off (presumably) gets stuck on.

[chris (Chris Jackson)]

@dakkar

hmmm is there any way, how to reset everything zwave related in openhab and start over from the beginning?

You can reset the controller using the “Hard Reset Controller” in the controller thing. This will completely reset the controller - as in factory reset.

@dakkar

Here a log snipplet of a failing inclusion:

There is nothing “failing” here - it looks perfectly fine - it just doesn’t find any devices that are in inclusion mode.

[chris (Chris Jackson)]

I think I’ve found a corner case where the hold-off timer can be set on, but the timer not started. This should be fixed here.

[5iver (Scott Rushworth)]

Cool! Still want a log?

[5iver (Scott Rushworth)]

Wow! That was the quickest, cleanest binding restart I think I’ve ever seen! And not dead nodes! Fingers crossed that doesn’t change.

Edit: Never mind… up to 8 dead nodes.

[chris (Chris Jackson)]

@5iver

Cool! Still want a log?

If it’s no problem, then I would like to confirm my theory. If not, we’ll just wait and see if it’s fixed

@5iver

up to 8 dead nodes.

I would have been REALLY surprised if it wasn’t the same as before (with hopefully the fact that it now doesn’t get stuck in the hold-off ON state after some time)…

Are all of these battery nodes?

[5iver (Scott Rushworth)]

Yes. Up to 16 now. I’ll send the log from before.

[chris (Chris Jackson)]

@5iver can you give this a try. I’d be interested to see how the battery devices work with this - it just bumps the priority of their transactions.