As I mentioned in title, I experiencing frustrating problem.
When openHAB/z-wave controller (Aeotec ZW090) mark (some) node(s) as failed (probably by mistake), and then if openHAB restarts, openHAB at startup removes these nodes.
Every time I restored ZW090 from backup using special tools, but it is not the solution.
To confirm:
Devices/nodes marked as failed are working properly and after restore ZW090 configuration and openHAB restart again.
Environment details:
OpenHab 2.1.0
Aeotec ZW090 Z-Wave controller
Question:
Have someone similar problem ?
If yes, there is any solution ?
PS.
Generally, I understand that controller can mark some nodes as failed, but removing from the network should be confirmed by operator and never have to be done automatically.
Do you mean the Things are being removed from OH, or the nodes are being removed from the zwave network and you can’t even see them in Zensys Tools or other software?
@5iver,
That mean “the nodes are being removed from the zwave network and you can’t even see them in Zensys Tools or other software” (tested with Zensys Tools and open-zwave-control-panel and obviously with habmin)
But You have to know, that only controller removes nodes (it is not exclusion process) but nodes still “think” that there are in the network and after configuration restore (using Aeon Labs Z-Stick Gen5 Backup Tool) all start to working well (for hours, day or weeks - there is no rule)
I may have seen something similar then, but I don’t think it is caused by the zwave binding. I had the stick get into a strange state after replacing failed nodes, where specific nodes would randomly disappear and reappear. I finally excluded the troublesome nodes and it cleared up. I’m about due for an annual wipe of the network and rebuild from scratch… it’s painful but worth it.
It also seems like USB zwave controllers need/like an occasional reboot. I found out that the USB ports in my system don’t power down during a restart, so restarting the system wasn’t enough. Powering down or unplugging it works.
If you’re running the 2.1 zwave binding, it’s getting pretty dated. If this is related to the binding or OH in some way, you may want to try upgrading. I really doubt that this is specifically caused by the binding though.
I see one common thing: I also replaced failed node(s).
Unfortunately, about:
for me is quite big problem, in my network I have 55 nodes (and I planning to add new) so rebuilding from scratch is not good idea… and could persuade me to change technology…
In my situation, nodes randomly disappear but never reappear. Moreover there are not nodes which have been replaced because of failure.
@5iver, thank a lot for Your problem description
Now I know, that it is not only my problem
Maybe someone else has similar and could describe his experience - maybe solution.
On next step I will try to contact AeonLabs, maybe they have any idea how to do besides “rebuild network from scratch”
I would suggest to try and get a log of what is happening. Is the list of devices contained in the controller simply changing each time the binding starts, or is there something causing the nodes to disappear. It’s not something I’ve ever seen, but I guess if the NV memory was corrupted in the stick, it could happen.
2018-03-09 17:14:46.219 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyZWave0'
2018-03-09 17:14:46.302 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2018-03-09 17:14:46.326 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - Update networkKey
2018-03-09 17:14:46.393 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2018-03-09 17:14:46.395 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
(...)
2018-03-09 17:14:49.681 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2018-03-09 17:14:49.682 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2018-03-09 17:14:49.682 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 3: Node found
2018-03-09 17:14:49.682 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 4: Node found
2018-03-09 17:14:49.682 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 5: Node found
2018-03-09 17:14:49.683 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 6: Node found
2018-03-09 17:14:49.683 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 7: Node found
2018-03-09 17:14:49.683 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 8: Node found
2018-03-09 17:14:49.683 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 9: Node found
2018-03-09 17:14:49.684 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 10: Node found
2018-03-09 17:14:49.684 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 11: Node found
2018-03-09 17:14:49.684 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 12: Node found
2018-03-09 17:14:49.684 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 13: Node found
2018-03-09 17:14:49.685 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 14: Node found
2018-03-09 17:14:49.685 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 15: Node found
2018-03-09 17:14:49.685 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 16: Node found
2018-03-09 17:14:49.685 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 17: Node found
2018-03-09 17:14:49.686 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 18: Node found
2018-03-09 17:14:49.686 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 19: Node found
2018-03-09 17:14:49.686 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 20: Node found
2018-03-09 17:14:49.686 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 21: Node found
2018-03-09 17:14:49.686 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 22: Node found
2018-03-09 17:14:49.687 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 23: Node found
2018-03-09 17:14:49.687 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 24: Node found
2018-03-09 17:14:49.687 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 25: Node found
2018-03-09 17:14:49.688 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 26: Node found
2018-03-09 17:14:49.689 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 27: Node found
2018-03-09 17:14:49.689 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 28: Node found
2018-03-09 17:14:49.689 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 29: Node found
2018-03-09 17:14:49.690 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 30: Node found
2018-03-09 17:14:49.690 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 31: Node found
2018-03-09 17:14:49.690 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 32: Node found
2018-03-09 17:14:49.690 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 33: Node found
2018-03-09 17:14:49.691 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 34: Node found
2018-03-09 17:14:49.691 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 35: Node found
2018-03-09 17:14:49.691 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 36: Node found
2018-03-09 17:14:49.691 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 37: Node found
2018-03-09 17:14:49.692 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 38: Node found
2018-03-09 17:14:49.692 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 39: Node found
2018-03-09 17:14:49.692 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 40: Node found
2018-03-09 17:14:49.692 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 41: Node found
2018-03-09 17:14:49.693 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 42: Node found
2018-03-09 17:14:49.693 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 43: Node found
2018-03-09 17:14:49.693 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 44: Node found
2018-03-09 17:14:49.693 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 45: Node found
2018-03-09 17:14:49.694 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 46: Node found
2018-03-09 17:14:49.694 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 47: Node found
2018-03-09 17:14:49.694 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 48: Node found
2018-03-09 17:14:49.695 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 49: Node found
2018-03-09 17:14:49.695 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 50: Node found
2018-03-09 17:14:49.695 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 51: Node found
2018-03-09 17:14:49.695 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 52: Node found
2018-03-09 17:14:49.696 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 53: Node found
2018-03-09 17:14:49.696 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 54: Node found
2018-03-09 17:14:49.696 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 55: Node found
2018-03-09 17:14:49.697 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2018-03-09 17:14:49.697 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2018-03-09 17:14:49.697 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2018-03-09 17:14:49.698 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 55
2018-03-09 17:14:49.698 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
And log with one node removed, when I’ve restarted OH few days later (for sure I did not remove this node) (NODE 49 have been unexpectedly removed):
2018-03-11 12:01:32.067 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyZWave0'
2018-03-11 12:01:32.347 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2018-03-11 12:01:32.378 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - Update networkKey
2018-03-11 12:01:32.506 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2018-03-11 12:01:32.507 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
(...)
2018-03-11 12:01:35.862 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 1: Node found
2018-03-11 12:01:35.863 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 2: Node found
2018-03-11 12:01:35.863 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 3: Node found
2018-03-11 12:01:35.863 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 4: Node found
2018-03-11 12:01:35.864 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 5: Node found
2018-03-11 12:01:35.864 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 6: Node found
2018-03-11 12:01:35.864 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 7: Node found
2018-03-11 12:01:35.865 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 8: Node found
2018-03-11 12:01:35.865 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 9: Node found
2018-03-11 12:01:35.865 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 10: Node found
2018-03-11 12:01:35.865 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 11: Node found
2018-03-11 12:01:35.866 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 12: Node found
2018-03-11 12:01:35.866 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 13: Node found
2018-03-11 12:01:35.866 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 14: Node found
2018-03-11 12:01:35.866 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 15: Node found
2018-03-11 12:01:35.867 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 16: Node found
2018-03-11 12:01:35.867 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 17: Node found
2018-03-11 12:01:35.867 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 18: Node found
2018-03-11 12:01:35.867 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 19: Node found
2018-03-11 12:01:35.867 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 20: Node found
2018-03-11 12:01:35.868 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 21: Node found
2018-03-11 12:01:35.868 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 22: Node found
2018-03-11 12:01:35.868 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 23: Node found
2018-03-11 12:01:35.868 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 24: Node found
2018-03-11 12:01:35.869 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 25: Node found
2018-03-11 12:01:35.869 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 26: Node found
2018-03-11 12:01:35.869 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 27: Node found
2018-03-11 12:01:35.869 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 28: Node found
2018-03-11 12:01:35.870 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 29: Node found
2018-03-11 12:01:35.870 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 30: Node found
2018-03-11 12:01:35.871 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 31: Node found
2018-03-11 12:01:35.871 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 32: Node found
2018-03-11 12:01:35.871 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 33: Node found
2018-03-11 12:01:35.871 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 34: Node found
2018-03-11 12:01:35.872 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 35: Node found
2018-03-11 12:01:35.872 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 36: Node found
2018-03-11 12:01:35.872 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 37: Node found
2018-03-11 12:01:35.872 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 38: Node found
2018-03-11 12:01:35.873 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 39: Node found
2018-03-11 12:01:35.873 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 40: Node found
2018-03-11 12:01:35.873 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 41: Node found
2018-03-11 12:01:35.873 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 42: Node found
2018-03-11 12:01:35.874 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 43: Node found
2018-03-11 12:01:35.874 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 44: Node found
2018-03-11 12:01:35.875 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 45: Node found
2018-03-11 12:01:35.875 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 46: Node found
2018-03-11 12:01:35.875 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 47: Node found
2018-03-11 12:01:35.875 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 48: Node found
2018-03-11 12:01:35.876 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 50: Node found
2018-03-11 12:01:35.876 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 51: Node found
2018-03-11 12:01:35.876 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 52: Node found
2018-03-11 12:01:35.876 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 53: Node found
2018-03-11 12:01:35.877 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 54: Node found
2018-03-11 12:01:35.877 [INFO ] [age.SerialApiGetInitDataMessageClass] - NODE 55: Node found
2018-03-11 12:01:35.877 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2018-03-11 12:01:35.877 [INFO ] [age.SerialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2018-03-11 12:01:35.878 [INFO ] [age.SerialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2018-03-11 12:01:35.878 [INFO ] [age.SerialApiGetInitDataMessageClass] - # Nodes = 54
2018-03-11 12:01:35.879 [INFO ] [age.SerialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
In this case only one node have been removed, but often is more and always different nodes are removed.
According:
It have been my first idea, so I’ve bought new one, the same model, but 1.5 year younger , for sure from different series.
Unfortunately problem still persist.
PS.
Few years ago I have used Aeotec Z-Stick S2 (DSA02203-ZWUE) and I have never experienced this kind of behavior…
Interesting - if possible, can you get this as a debug log so I can double check that there’s really a bad response from the stick, and not something wrong in the binding (I think this is unlikely, but I’d like to double check if possible). Also, there’s another log message just above this that prints the number of nodes found - can you also add this to the log info above?
------------Number of Nodes Found Registered to ZWave Controller------------
# Nodes = 55
----------------------------------------------------------------------------
which have been included in last post.
Could You give an example ?
Do You thing, start OH by start_debug.sh and bring You openhab.log ?
@chris I have one more observation, if something start to be wrong (and next I loosing Z-Wave nodes), OH starts to consume more and more CPU, sometime up to 100%. Unfortunately, I’ve started registering CPU load for few weeks and I have no good history to compare/correlate problem occurrence and CPU load.
More over, this observation/behavior could be confusing and could be effect of completely different problem.
I don’t see it in the last post though? I assume you mean you edited the log parts, but I don’t see this and the forum does not show any edits to your post…
Sorry - what do you want an example of?
This will not enable debug logging. You need to enable debug with the log:set debug org.binding.openhab.zwave command.
When looking for this, be sure to check the configuration that PaperUI sends. The only way that the binding will remove a device is if the UI sends a remove device configuration. HABmin never does this unless you click on this option. PaperUI will send this every time you update the configuration of a device - if for some reason it sends the wrong state, then the device will potentially be removed by the binding.
I bought Z-Way module and it seems that problem does not exists anymore.
(
Reason:
Aeon Labs Z-Stick is “shit”, two modules from two different lot has similar problems - nodes have been randomly removed.
With time more and more.
Maybe sugestion that is EEPROM problem is accurate.
)
