Openhab General Z-Wave Problem

[soists (Lennart)]

• Platform information:

  • Hardware: amd64 8GB 240GB
  • OS: Debian 10.9
  • Java Runtime Environment: OpenJDK Runtime Environment Zulu11.48+21-CA (When opening the ticket: OpenJDK Runtime Environment Zulu11.41+23)
  • openHAB version: 3.1.0 (When opening the ticket: 3.0.1 Release Build)

• Issue of the topic:
  Communication bridge Z-Wave won’t work anymore after months. Bridge appears Online and so do all devices, but wont react to any commands in Panels. Openhab also randomly restarts when using the mobile app.

• Startup Log

2021-07-09 21:17:05.133 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
2021-07-09 21:17:05.764 [INFO ] [e.automation.internal.RuleEngineImpl] - Rule engine started.
2021-07-09 21:17:10.416 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2021-07-09 21:17:10.416 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2021-07-09 21:17:12.906 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 17: Not initialized (ie node unknown), ignoring message.
2021-07-09 21:17:13.083 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 17: Not initialized (ie node unknown), ignoring message.
2021-07-09 21:17:13.265 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 17: Not initialized (ie node unknown), ignoring message.
2021-07-09 21:17:13.853 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 7: Restore from config: Error. Data invalid, ignoring config.
2021-07-09 21:17:13.891 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 12: Restore from config: Error. Data invalid, ignoring config.
2021-07-09 21:17:44.296 [WARN ] [core.karaf.internal.FeatureInstaller] - The misc add-on 'ruleengine' does not exist - ignoring it.
2021-07-09 21:17:44.306 [WARN ] [core.karaf.internal.FeatureInstaller] - The ui add-on 'restdocs' does not exist - ignoring it.
2021-07-09 21:17:44.307 [WARN ] [core.karaf.internal.FeatureInstaller] - The ui add-on 'classic' does not exist - ignoring it.
2021-07-09 21:17:44.308 [WARN ] [core.karaf.internal.FeatureInstaller] - The ui add-on 'habmin' does not exist - ignoring it.
2021-07-09 21:17:44.309 [WARN ] [core.karaf.internal.FeatureInstaller] - The ui add-on 'paper' does not exist - ignoring it.
2021-07-09 21:18:06.240 [WARN ] [e.californium.scandium.DTLSConnector] - Shutdown DTLS connector on [0.0.0.0/0.0.0.0:52549] executor not terminated in time!
2021-07-09 21:19:08.783 [WARN ] [e.californium.scandium.DTLSConnector] - Shutdown DTLS connector on [0.0.0.0/0.0.0.0:42618] executor not terminated in time!
2021-07-09 21:19:40.305 [WARN ] [e.californium.scandium.DTLSConnector] - Shutdown DTLS connector on [0.0.0.0/0.0.0.0:60903] executor not terminated in time!

• Shutdown Log

2021-07-09 21:16:22.525 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 26: Error in initialization thread
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@5b83dc8a[Not completed, task = org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter@1e81413e] rejected from java.util.concurrent.ThreadPoolExecutor@675b6ee[Shutting down, pool size = 18, active thr
eads = 18, queued tasks = 0, completed tasks = 102]
        at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2055) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:825) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1355) ~[?:?]
        at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransactionAsync(ZWaveTransactionManager.java:1191) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1203) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendTransaction(ZWaveController.java:532) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode.sendTransaction(ZWaveNode.java:1381) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:289) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:264) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.doInitialStages(ZWaveNodeInitStageAdvancer.java:434) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$1.run(ZWaveNodeInitStageAdvancer.java:188) [bundleFile:?]
2021-07-09 21:16:23.156 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 30: Error in initialization thread
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@2437995b[Not completed, task = org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter@20080982] rejected from java.util.concurrent.ThreadPoolExecutor@675b6ee[Shutting down, pool size = 18, active threads = 18, queued tasks = 0, completed tasks = 102]
        at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2055) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:825) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1355) ~[?:?]
        at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransactionAsync(ZWaveTransactionManager.java:1191) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1203) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendTransaction(ZWaveController.java:532) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode.sendTransaction(ZWaveNode.java:1381) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:289) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:264) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.doInitialStages(ZWaveNodeInitStageAdvancer.java:434) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$1.run(ZWaveNodeInitStageAdvancer.java:188) [bundleFile:?]
2021-07-09 21:16:25.586 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Error in initialization thread
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@5b09e392[Not completed, task = org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter@5f366cac] rejected from java.util.concurrent.ThreadPoolExecutor@675b6ee[Shutting down, pool size = 18, active threads = 18, queued tasks = 0, completed tasks = 102]
        at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2055) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:825) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1355) ~[?:?]
        at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:140) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransactionAsync(ZWaveTransactionManager.java:1191) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1203) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendTransaction(ZWaveController.java:532) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode.sendTransaction(ZWaveNode.java:1381) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:289) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:264) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.doInitialStages(ZWaveNodeInitStageAdvancer.java:434) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$1.run(ZWaveNodeInitStageAdvancer.java:188) [bundleFile:?]
2021-07-09 21:16:25.887 [WARN ] [core.thing.internal.ThingManagerImpl] - Disposing handler for thing 'zwave:serial_zstick:70cce884' takes more than 5000ms.

[rossko57]

@soists

Openhab also randomly restarts when using the mobile app.

That hints at more fundamental problems than just zwave

@soists

2021-07-09 21:17:44.307 [WARN ] [core.karaf.internal.FeatureInstaller] - The ui add-on 'classic' does not exist - ignoring it.

You’ve got a lot of old OH2 stuff in your addons.cfg file still, that cannot be installed. I wonder if something unwanted is getting installed?

[soists (Lennart)]

@rossko57

That hints at more fundamental problems than just zwave

Yes - any idea how to track this down?
The Z-Wave problem seems to be only consiting of a changed serial port id. For some reason it is changing back and forth from ttyACM0 to ttyACM1 and so OH can’t connect anymore.

@rossko57

You’ve got a lot of old OH2 stuff in your addons.cfg file still, that cannot be installed. I wonder if something unwanted is getting installed?

I cleanup it up and also updated to 3.1. No more warnings about addons now and looking like this now:

> config:property-list
   action =
   binding = astro,network,exec,telegram,smhi,spotify,tradfri,zwave
   package = standard
   persistence = influxdb
   transformation = map,regex,xslt,exec,javascript,scale,xpath,jsonpath
   ui = basic,habpanel

[Andrew_Rowe]

@soists

Communication bridge Z-Wave won’t work anymore after months

this is first statement of interest to me. This is a system that worked and an upgrade from OH2 to OH3 broke it?

@soists

The Z-Wave problem seems to be only consiting of a changed serial port id. For some reason it is changing back and forth from ttyACM0 to ttyACM1 and so OH can’t connect anymore.

ok so serial problem.

warning: I’m talking about something I know very little about and may not be calling stuff by it’s proper term

I’ve never had to do it but some linux users (I think) have to create a sim link (or something like that) to the port so the operating system consistently assigns the same port number over restarts and such.

anyhow… search this forum for zwave and serial and you will see a lot of chatter about it lately. Set the search to search by ‘most recent’ to see problem folks have had with OH3 and the serial stuff lately.

@soists

@rossko57

You’ve got a lot of old OH2 stuff in your addons.cfg file still, that cannot be installed.

I cleanup it up and also updated to 3.1. No more warnings about addons now

OK, that is one OH2 to OH3 migration problem solved. This issue was know to cause restart loops that manifested themselves in some strange ways. So hopefully the system becomes stable and you can track down the serial issue

edit to add:
check this other thread for tips to diagnose

Z-Wave USB stick not working after OH 3.1 update

Hi! I have an issue with my Aeotec gen 5 Z-wave stick which has stopped working after I upgraded from OH 3.0.x to 3.1 recently. And I need help getting it working again. Here is a debug log of the binding (and the serial binding) when I enable my z-wave thing: 2021-07-10 15:45:47.469 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:ebf2caa1 with scan time of 60 2021-07-10 15:45:47.475 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWa…

[soists (Lennart)]

@Andrew_Rowe

this is first statement of interest to me. This is a system that worked and an upgrade from OH2 to OH3 broke it?

I think the upgrade to OH3 is not the reason for it. I did the upgrade quite some time ago and the problems only occured recently. (Need to note I might havn’t cleaned the cache after the upgrade back then)

@Andrew_Rowe

I’ve never had to do it but some linux users (I think) have to create a sim link (or something like that) to the port so the operating system consistently assigns the same port number over restarts and such.

I had the symlink, but it never worked out because of permission problem. Just now fixed the permissions on the symlink, so the serial id shouldn’t be a problem anymore. Also bridge doensn’t appear as broken anymore in the UI and all devices appear as online. I can uses all the switches, but the devices don’t update anymore. Also the logs show the controller is beeing restarted regulary with some thread problems occuring

2021-07-11 11:28:29.985 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2021-07-11 11:28:29.986 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2021-07-11 11:28:29.989 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 17: Not initialized (ie node unknown), ignoring message.
2021-07-11 11:28:29.991 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 17: Not initialized (ie node unknown), ignoring message.
2021-07-11 11:28:33.131 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 7: Restore from config: Error. Data invalid, ignoring config.
2021-07-11 11:28:33.183 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 12: Restore from config: Error. Data invalid, ignoring config.
2021-07-11 11:32:43.293 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 11: Error in initialization thread
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@22f51c[Not completed, task = org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter@1d7f87] rejected from java.util.concurrent.ThreadPoolExecutor@12075bc[Shutting down, pool size = 5, active threads = 5, queued tasks = 0, completed tasks = 193]
        at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(Unknown Source) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.reject(Unknown Source) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.execute(Unknown Source) ~[?:?]
        at java.util.concurrent.AbstractExecutorService.submit(Unknown Source) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransactionAsync(ZWaveTransactionManager.java:1191) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1203) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendTransaction(ZWaveController.java:532) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode.sendTransaction(ZWaveNode.java:1381) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:289) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:264) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.doInitialStages(ZWaveNodeInitStageAdvancer.java:434) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$1.run(ZWaveNodeInitStageAdvancer.java:188) [bundleFile:?]
2021-07-11 11:32:43.456 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Error in initialization thread
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@83420a[Not completed, task = org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter@bcd805] rejected from java.util.concurrent.ThreadPoolExecutor@12075bc[Shutting down, pool size = 5, active threads = 5, queued tasks = 0, completed tasks = 193]
        at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(Unknown Source) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.reject(Unknown Source) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.execute(Unknown Source) ~[?:?]
        at java.util.concurrent.AbstractExecutorService.submit(Unknown Source) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransactionAsync(ZWaveTransactionManager.java:1191) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1203) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendTransaction(ZWaveController.java:532) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode.sendTransaction(ZWaveNode.java:1381) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:289) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:264) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.doInitialStages(ZWaveNodeInitStageAdvancer.java:434) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$1.run(ZWaveNodeInitStageAdvancer.java:188) [bundleFile:?]
2021-07-11 11:32:44.031 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 23: Error in initialization thread
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@1542e3[Not completed, task = org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter@2ac27e] rejected from java.util.concurrent.ThreadPoolExecutor@12075bc[Shutting down, pool size = 5, active threads = 5, queued tasks = 0, completed tasks = 193]
        at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(Unknown Source) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.reject(Unknown Source) ~[?:?]
        at java.util.concurrent.ThreadPoolExecutor.execute(Unknown Source) ~[?:?]
        at java.util.concurrent.AbstractExecutorService.submit(Unknown Source) ~[?:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransactionAsync(ZWaveTransactionManager.java:1191) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1203) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveController.sendTransaction(ZWaveController.java:532) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.ZWaveNode.sendTransaction(ZWaveNode.java:1381) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:289) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:264) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.doInitialStages(ZWaveNodeInitStageAdvancer.java:434) ~[bundleFile:?]
        at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$1.run(ZWaveNodeInitStageAdvancer.java:188) [bundleFile:?]
2021-07-11 11:33:21.398 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2021-07-11 11:33:21.399 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2021-07-11 11:33:21.401 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 17: Not initialized (ie node unknown), ignoring message.
2021-07-11 11:33:21.403 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 17: Not initialized (ie node unknown), ignoring message.
2021-07-11 11:33:23.682 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 17: Not initialized (ie node unknown), ignoring message.
2021-07-11 11:33:24.002 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 17: Not initialized (ie node unknown), ignoring message.
2021-07-11 11:33:24.113 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 17: Not initialized (ie node unknown), ignoring message.
2021-07-11 11:33:24.224 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 17: Not initialized (ie node unknown), ignoring message.
2021-07-11 11:33:24.542 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 7: Restore from config: Error. Data invalid, ignoring config.
2021-07-11 11:33:24.594 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 12: Restore from config: Error. Data invalid, ignoring config.
2021-07-11 11:53:50.182 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2021-07-11 11:53:50.182 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2021-07-11 11:53:50.184 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 17: Not initialized (ie node unknown), ignoring message.
2021-07-11 11:53:50.186 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 17: Not initialized (ie node unknown), ignoring message.
2021-07-11 11:53:52.943 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 17: Not initialized (ie node unknown), ignoring message.
2021-07-11 11:53:53.124 [WARN ] [nal.protocol.ZWaveTransactionManager] - NODE 17: Not initialized (ie node unknown), ignoring message.
2021-07-11 11:53:53.343 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 7: Restore from config: Error. Data invalid, ignoring config.
2021-07-11 11:53:53.374 [WARN ] [ve.internal.protocol.ZWaveController] - NODE 12: Restore from config: Error. Data invalid, ignoring config.

@Andrew_Rowe

check this other thread for tips to diagnose

Thanks for linking - I had checked out this thread, but thought these are different problems.

[soists (Lennart)]

An interesting observation as a sidenow: I use a Aeontec Z Stick Gen 5, which does blink in several colours. Just now I found it in a state, where it did blink without a “black” between colours. So it constantly changed the colour after colour and normally the led is off for a secound before a new colour is appearing.

[Andrew_Rowe]

@soists

Also bridge doensn’t appear as broken anymore in the UI and all devices appear as online. I can uses all the switches, but the devices don’t update anymore.

So what you are saying is that you have zwave light switches and they work when the switch is manually switched (turns the light on or off) but their status doesn’t update in the user interface of openHAB correct?

The log snippet does appear to indicate the controller is restarting every 5 minutes or so. With all that going on, it is surprising the switches function

Has this log been filtered? Is logging for zwave set to debug? (if not instructions are in the binding docs) How old is the controller? How many nodes are in the system?

With the description of the lights on the controller, I’m sort of suspecting the controller, perhaps ordering a spare might be a good idea. Hopefully Chris will have a look at this thread and provide some insight into the log entries

[apella12 (Bob Eckhoff)]

Chris is the expert and I am not, however reading the logs your devices are getting hung up in initialization (ZwaveNodeInitStageadvancer). This class is called on startup and checks the nodes to see if they exist (node17- does not appear to exist) or restore from config (lie the 7 & 12 errors). It also handles the inclusion on new devices and the heal routines (but you are not there yet).

I’m assuming in upgrading you ran openhab-cli clean-cache? If not, that is an easy first step. Also do not know how many nodes you have but 17, 7, 12,11, 23 and 3 are not getting initialized. Are there others that are working? Another easy step could be to delete the XML files for 7 and 12 in the userdata/zwave folder as they will be recreated if initialization completes. It seems the error says the configuration is faulty, so that might work for those two. Lastly if it was me I would try exclude a node using the UI (or use the Silabs PC controller to force remove them- It may not be possible to delete using the UI since they are not initialized), then delete the thing from the UI, reset the device to factory default and try to include again. If you want to wait for Chris, you probably need to run the binding in debug mode as Andrew suggested.

Don’t know how this got so messed up, but it might be time to clear the decks (so to speak)

Bob

Edit: I had one additional idea before you start deleting nodes. Uninstall the zwave binding. Shut down OH. Use the clean-cache. Start OH. Does everything else , except obviously zwave nodes, work cleanly? If any problems at that point might want to fix them first. After all is good, then install zwave again and proceed as above.

[chris (Chris Jackson)]

@soists

Also the logs show the controller is beeing restarted regulary with some thread problems occuring

It’s really hard to tell what is happening in the logs as there’s no debug information. I’d strongly suggest to enable debug - it will really help understand the issue.

@soists

Also the logs show the controller is beeing restarted regulary with some thread problems occuring

I think the exception is just caused by timing during shutdown - so it’s probably an effect and not related to the issue. Again - debug logging would help a lot to understand this.