This is my fear as well. I thought Z-wave devices could not interact with the network until they were included. If true, then the Zwave security is broken. My other thought was that this was a peer-peer communication, and I did have a node that did not have its association group set to “controller”.
With that script, will I have to delete and re-add my things?
Should I throw in the towel and put my Z-wave things in a file instead of letting OH manage them?
Just delete the Things from OH & re-discover. They will keep the same IDs but be updated by the binding. Your Items & rules will not need to be changed.
You do not need to exclude them from the network. Just delete from OH & re-discover. That would also be recommended if you were using manual Things files, but I am not sure the developer supports that any more for Z-Wave.
1 Like
At first I thought, cool, but this means I’ll have to re-enter the specific device configuration. For example, I have six thermostats, and I’ll have to set the names again.
I looked at manual things file, and I’m not keen on that. It would be nice to somehow decouple the thing names into a file.
I suppose if I bound my items to the Z-wave thing channels, this would be a moot problem. I just looked, and my items are bound to channels. Don’t know what I was thinking. So, this should be easy.
I upgraded my install to the latest snapshot (2.5.0-SNAPSHOT Build #1728). Good news, my devices so far have been stable/not going offline, and the TODO error is gone. The bad news is I have some really weird addressing issues that I don’t think are openhab’s fault.
My 3 new devices are still off at the breaker, but two are showing online in openhab, and something appears to respond to commands just enough that they get kept online. And then there’s Node 27, which just showed back up in my inbox. The problem is there is no node 27 on the network. Or at least there shouldn’t be.
When I originally switched from SmartThings to OpenHab back in May, I kept having an issue with devices not being fully discovered and showing up as “Unknown Device” in the inbox. When that happened, I’d exclude them then rediscover, and they’d normally come online properly with the next ID in sequence. So the device that started out as Node 27 was excluded and re-paired and has been functioning properly as Node 28.
Does this hold true during the discovery process? I believe I tried that and it didn’t work (device shows up as unknown and doesn’t resolve within a few minutes, delete from inbox and rerun discovery, device still shows as unknown).
I think my project this evening is to rebuild my zwave network from scratch. Looks like I picked the wrong week to quit sniffing glue.
If a device doesn’t fully discover during the pairing process, what is the proper procedure (obviously excluding and re-paring is incorrect)?
Manual Thing files are absolutely supported… basically a requirement for an official binding. The trouble with them is that OH dies not support updating Thing definitions, so Things need to be deleted and rediscovered to pull in an updated definition. I tried to explain here…
Labels and locations… yes, but this can be easily added into the script that I wrote, so that they will be restored. Configuration parameters… no, these will be read in from the device and updated in OH.
If they are still included in the network, the controller is reporting to the binding that the devices exist. The online/offline logic is tricky to get right and is not perfect. BUT, you should not keep device powered off, especially mains powered devices. These are routing devices and the mesh needs them. If you are not using them, then exclude the devices from the network.
… oops, sorry! 5 years ST free!
If your device is battery powered, wake it up several times to complete the discovery and initialization. Then add it in from the inbox. If it is a mains powered device, make sure it is in the device database and that the binding you are using is up to date, and also make sure that your zwave mesh is healthy… maybe take a look at a sniffer trace.
It’s actually a very good week for it!!! 
Thanks for the correction.
All looks very odd. Sadly sounds like Zwave is great until it is not. We all know 99% of the time adding a couple of devices is not be a big issue so it is always strange when it does.
Please could you help with some research into generic zwave issues and possibly yourself.
- look for “phantom” associations. see below
- has the traffic increased across some hot nodes and you are now getting latency. Any chance you could post a zniffer
- then exclude the new devices from the network see if the network heels
- if it does add them back in and see if it breaks
I think that possibly in the latest snapshot, the poll after command option is not working but it would need a busy poor route to be an issue and not sure why it would cause those logs. I have purposely caused excess traffic on a poor route and while the network pauses and goes bad, openHab handles it well. OpenHAB may be sending a report request after every command with almost no delay so you might have gained a busy route. I need to analyse my zniffer logs a bit more for more devices to be sure there is a general issue.
Phantom associations is a term that a friend uses to describe associations that were surely not set but appear on devices with node IDs that never existed in your network. I am busy testing for them but have not found them on my openHaq network yet. People have reported them on HC2 and various systems that use openzwave networks so it does appear to be independent of controller and possibly an issue with some devices so may not be relevant.
thanks,
Robert
Correct - and not just a requirement either. The binding doesn’t know at all if the configuration comes from a file or the database - it just gets configuration information.
I’ve not seen any reports of this (although I’ve been very busy so may have missed them). Why do you think this isn’t working? I don’t think anything has changed recently so it would be a surprise.
ZWave has very (Very!) poor error checking so it’s not uncommon for frames to get corrupted unfortunately.
that is truth
I have seen it for just from one zniffer on one device but certainly for this one device it has requested a report immediately after the command every time. I need to get a few more devices tested and of course it could be a UI issue.
One thing to be careful of, and that is when timing starts. The poll is timed from the time the command is queued, and not from the time it is sent. So, if there are delays in that transaction, then the poll will also be queued, and it could therefore be sent immediately after the response from the command.
I tried setting the poll after to disabled and still got a report request and set to a large value and it still was almost immediate. As I said I have not dug deeper yet so could be an issue with UI not setting the value.
Just check the logs - it will be pretty clear as there is a statement logged -:
NODE {}: Polling initialised at {} seconds - start in {} milliseconds.
Thanks that will make it easier.
Chris,
It is not that then as that line is not in the log.
You can see the issue here.
The first command is the set from 1 to 66. you can not see first hop as zniffer is out of range of controller
The second is a request for a report from 1 to 66.
The last is the report returned by the node 66 to 1.
What I can see in the log s similar stuff to that posted above. I am sure it was not like that until I took the snapshot.
It’s not super easy to work this out - I agree there are multiple commands being sent in reasonably quick succession, but I can’t decode the data in my head.
Can you provide the debug log for this sequence so I can see what the binding thinks it’s doing?
I will search it out.
There is another picture with the original request highlighted but i did not take a snip of the middle request for a report.
Not sure it is exact instance. You can see it sent a set quickly followed by a get. This was on an earlier snapshot. All that was done was change the setting.
2019-10-12 18:17:28.769 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Command received zwave:device:fac755a5:node66:protection_local5 → 0 [DecimalType]
2019-10-12 18:17:28.770 [DEBUG] [l.converter.ZWaveProtectionConverter] - NODE 66: Protection command PROTECTION_LOCAL received for 0
2019-10-12 18:17:28.770 [DEBUG] [andclass.ZWaveProtectionCommandClass] - NODE 66: Creating new message for command PROTECTION_SET
2019-10-12 18:17:28.771 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 66: Encapsulating message, instance / endpoint 5
2019-10-12 18:17:28.771 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 66: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 5
2019-10-12 18:17:28.771 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 66: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2019-10-12 18:17:28.772 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 66: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2019-10-12 18:17:28.772 [DEBUG] [l.converter.ZWaveProtectionConverter] - NODE 66: Sending Message: org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@783112b7
2019-10-12 18:17:28.772 [DEBUG] [andclass.ZWaveProtectionCommandClass] - NODE 66: Creating new message for command PROTECTION_GET
2019-10-12 18:17:28.773 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 66: Encapsulating message, instance / endpoint 5
2019-10-12 18:17:28.773 [DEBUG] [class.ZWaveMultiInstanceCommandClass] - NODE 66: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 5
2019-10-12 18:17:28.774 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 66: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL
2019-10-12 18:17:28.774 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 66: Command Class COMMAND_CLASS_MULTI_CHANNEL is NOT required to be secured
2019-10-12 18:17:28.774 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: Adding to device queue
2019-10-12 18:17:28.775 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: Added 926 to queue - size 4
So that was on a snapshot earlier this week. Then I took the snapshot from 17th and while it is working I am also getting odd todo that I can not see prior to this.
Not surprised by the timeout as it is a stretched route with a few nodes at the end but not sure about this.
2019-10-18 00:32:31.034 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 66: TID 985: Timeout at state WAIT_REQUEST. 3 retries remaining.
2019-10-18 00:32:31.034 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 985: Transaction is current transaction, so clearing!!!
2019-10-18 00:32:31.035 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 985: Transaction CANCELLED
2019-10-18 00:32:31.035 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 66: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-10-18 00:32:31.035 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 66: notifyTransactionResponse TID:985 CANCELLED
2019-10-18 00:32:31.036 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-10-18 00:32:31.036 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 985: Transaction event listener: DONE: CANCELLED →
2019-10-18 00:32:31.037 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 66: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@53dc3fa0
2019-10-18 00:32:34.488 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1C 00 49 40 42 16 04 07 01 5E 20 86 72 5A 59 85 73 84 80 71 56 70 31 8E 22 9C 98 7A 73
2019-10-18 00:32:34.489 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=66, callback=64, payload=40 42 16 04 07 01 5E 20 86 72 5A 59 85 73 84 80 71 56 70 31 8E 22 9C 98 7A
2019-10-18 00:32:34.489 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=66, callback=64, payload=40 42 16 04 07 01 5E 20 86 72 5A 59 85 73 84 80 71 56 70 31 8E 22 9C 98 7A
2019-10-18 00:32:34.490 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-10-18 00:32:34.490 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2019-10-18 00:32:34.490 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2019-10-18 00:32:34.491 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=66, callback=64, payload=40 42 16 04 07 01 5E 20 86 72 5A 59 85 73 84 80 71 56 70 31 8E 22 9C 98 7A
2019-10-18 00:32:34.491 [WARN ] [essage.ApplicationUpdateMessageClass] - TODO: Implement Application Update Request Handling of New ID Assigned (64).
2019-10-18 00:32:34.491 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
Also when it says canceled this is not a CAN from the serial interface when there is a buffer clash between putting a serial message into the controller when the buffer is in use by an inbound message but just a timeout. Is that correct?
I can’t really compare these two logs as they appear to be of different things. The first one is sending a command, and the second one doesn’t have this. It shows what is probably a timeout, but I’ve no idea what has timed out so it’s hard to really say what is happening.
Also, please can you format commands with code fences, or using the </> button rather than as a quote, or whatever, as that has added characters and it’s not super easy to read.
First one shows one issue and the other another. Not asking to compare.
The first log shows sending one command that i initiated
Creating new message for command PROTECTION_SET
and another that I did not.
Creating new message for command PROTECTION_GET
Is that not a bit odd?
The second only after I put on the later snapshot
what is that about?
This converter always seems to do this, so no, it’s not odd.
I don’t know. As I said above, it would be useful to see the command that was sent.