I am running 3 Z-Wave networks in my home, each with its own OH3 instance (on Windows 10). These 3 OH3-Zwave instances communicate with my main OH via the Remote OpenHab binding. This setup runs stable since 5 months and the Z-Wave networks are running stable since about 4 years.
But one of these networks has become very unstable since about 2 weeks. I did not change anything in setup but suddenly the Z-Wave binding stopped working with an error in Karaf Console:
2021-03-28 04:09:19.028 [WARN ] [ing.zwave.handler.ZWaveSerialHandler] - Got I/O exception Input/output error in writeArray during sending. exiting thread.
2021-03-28 04:09:19.639 [ERROR] [alization.ZWaveNodeInitStageAdvancer] - NODE 37: Error in initialization thread
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@472f6e55[Not completed, task = org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter@22de074] rejected from java.util.concurrent.ThreadPoolExecutor@6386401f[Shutting down, pool size = 53, active threads = 53, queued tasks = 0, completed tasks = 2994]
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.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:291) ~[bundleFile:?]
at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.processTransaction(ZWaveNodeInitStageAdvancer.java:264) ~[bundleFile:?]
at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer.doHealStages(ZWaveNodeInitStageAdvancer.java:1139) ~[bundleFile:?]
at org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeInitStageAdvancer$1.run(ZWaveNodeInitStageAdvancer.java:184) [bundleFile:?]
2021-03-28 04:09:30.119 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2021-03-28 04:09:30.119 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
So there is obviusly a communication problem between the binding and my Z-Stick. The binding seems to try to restart the stick, but nothing happens anymore. There are no more updates for the Z-Wave things, every communication ends.
A restart of OH can help, but after a period of time between 10 minutes to 12 hours the problem will repeat.
As I had not changed anything in my setup I suspected that the Aeon Stick was about to fail. So I took another fresh Z Stick and put the backup (taken with the Aeon backup tool,about 3 months old) to the new stick. OH restarted, but after 4 hours the same thing happened again.
I also tried two older backups, one from a year ago and one from 2 years ago. Same result.
I meanwhile tried even a third fresh Z Stick with backup to doublecheck, again the same result.
I also tried 2 other computers to run that OH instance (to make sure, that it is not a COM port problem with the hardware or drivers), but again the same result.
My other 2 Z-Wave networks run still perfectly with the same hardware, same software setup etc.
What can be the root cause of this? In the couple of hours until the error occurs again, everything in my network works absolutely smoothly and correct (as it did for 4 years). But then the Communication error appears again and everything is stalled. I just would like to understand the underlying problem before I start the time consuming job to reinclude all 50 devices to a new Z-Wave network (or whatever, maybe throwing away the Z-Wave stuff finally and buy Shellys…).
Any help or ideas would be highly aprreciated, thank you!
Here is a debug log showing the problems. The first I/O error happens at 2021-03-28 18:50:45.954, which then leads to the shutdown of the Z-Wave network by the binding but then several Java exceptions follow::
2021-03-28 18:50:45.735 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 19: TID 125: Timeout at state ABORTED. 3 retries remaining.
2021-03-28 18:50:45.735 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 125: Transaction is current transaction, so clearing!!!!!
2021-03-28 18:50:45.735 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 125: Transaction CANCELLED
2021-03-28 18:50:45.735 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2021-03-28 18:50:45.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: notifyTransactionResponse TID:125 CANCELLED
2021-03-28 18:50:45.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2021-03-28 18:50:45.735 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 46 FC
2021-03-28 18:50:45.735 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 46 FC
2021-03-28 18:50:45.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 125: Transaction event listener: DONE: CANCELLED ->
2021-03-28 18:50:45.735 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@3c65f7ec
2021-03-28 18:50:45.735 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Node Init transaction completed with response COMPLETE
2021-03-28 18:50:45.735 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Node advancer: VERSION - checking COMMAND_CLASS_ASSOCIATION, version is 0
2021-03-28 18:50:45.735 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: Node advancer: VERSION - queued COMMAND_CLASS_ASSOCIATION
2021-03-28 18:50:45.735 [DEBUG] [ommandclass.ZWaveVersionCommandClass] - NODE 19: Creating new message for application command VERSION_COMMAND_CLASS_GET command class COMMAND_CLASS_ASSOCIATION
2021-03-28 18:50:45.735 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 19: ZWaveCommandClassTransactionPayload - send to node
2021-03-28 18:50:45.735 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: SECURITY not supported
2021-03-28 18:50:45.735 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: Command Class COMMAND_CLASS_VERSION is NOT required to be secured
2021-03-28 18:50:45.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: sendTransaction org.openhab.binding.zwave.internal.protocol.transaction.ZWaveCommandClassTransactionPayload@6115f570
2021-03-28 18:50:45.954 [WARN ] [ing.zwave.handler.ZWaveSerialHandler] - Got I/O exception Input/output error in writeArray during sending. exiting thread.
2021-03-28 18:50:45.954 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Stopping ZWave network
2021-03-28 18:50:45.954 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Controller status changed to OFFLINE.
2021-03-28 18:50:45.954 [DEBUG] [ve.internal.protocol.ZWaveController] - Shutting down ZWave controller
2021-03-28 18:50:45.954 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Shutting down transaction manager
2021-03-28 18:50:45.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Controller is not online.
2021-03-28 18:50:45.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Controller status changed to OFFLINE.
2021-03-28 18:50:45.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: Controller is not online.
2021-03-28 18:50:45.970 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Exiting ZWave Receive Thread
2021-03-28 18:50:45.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 67: Controller status changed to OFFLINE.
2021-03-28 18:50:45.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 68: Controller status changed to OFFLINE.
2021-03-28 18:50:45.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 67: Controller is not online.
2021-03-28 18:50:45.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Controller status changed to OFFLINE.
2021-03-28 18:50:45.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 68: Controller is not online.
2021-03-28 18:50:45.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 69: Controller status changed to OFFLINE.
2021-03-28 18:50:45.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 69: Controller is not online.
2021-03-28 18:50:45.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: Controller is not online.
2021-03-28 18:50:45.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Controller status changed to OFFLINE.
2021-03-28 18:50:45.970 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: Controller is not online.
2021-03-28 18:50:45.980 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 27: Controller status changed to OFFLINE.
2021-03-28 18:50:45.980 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 27: Controller is not online.
2021-03-28 18:50:45.980 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 29: Controller status changed to OFFLINE.
2021-03-28 18:50:45.980 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 72: Controller status changed to OFFLINE.
2021-03-28 18:50:45.980 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 72: Controller is not online.
2021-03-28 18:50:45.980 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 30: Controller status changed to OFFLINE.
2021-03-28 18:50:45.980 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 30: Controller is not online.
2021-03-28 18:50:45.980 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Controller status changed to OFFLINE.
2021-03-28 18:50:45.996 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Controller is not online.
2021-03-28 18:50:45.996 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 77: Controller status changed to OFFLINE.
2021-03-28 18:50:45.996 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 77: Controller is not online.
2021-03-28 18:50:45.996 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 34: Controller status changed to OFFLINE.
2021-03-28 18:50:45.996 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 34: Controller is not online.
2021-03-28 18:50:45.996 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Controller status changed to OFFLINE.
2021-03-28 18:50:45.996 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 36: Controller is not online.
2021-03-28 18:50:45.996 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 37: Controller status changed to OFFLINE.
2021-03-28 18:50:45.996 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 37: Controller is not online.
2021-03-28 18:50:45.996 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 39: Controller status changed to OFFLINE.
2021-03-28 18:50:45.996 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 39: Controller is not online.
2021-03-28 18:50:45.996 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 70: Controller status changed to OFFLINE.
2021-03-28 18:50:46.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 70: Controller is not online.
2021-03-28 18:50:46.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 29: Controller is not online.
2021-03-28 18:50:46.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Controller status changed to OFFLINE.
2021-03-28 18:50:46.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 85: Controller is not online.
2021-03-28 18:50:46.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 86: Controller status changed to OFFLINE.
2021-03-28 18:50:46.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 86: Controller is not online.
2021-03-28 18:50:46.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Controller status changed to OFFLINE.
2021-03-28 18:50:46.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 42: Controller is not online.
2021-03-28 18:50:46.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 43: Controller status changed to OFFLINE.
2021-03-28 18:50:46.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 43: Controller is not online.
2021-03-28 18:50:46.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 88: Controller status changed to OFFLINE.
2021-03-28 18:50:46.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 88: Controller is not online.
2021-03-28 18:50:46.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 44: Controller status changed to OFFLINE.
2021-03-28 18:50:46.027 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 44: Controller is not online.
2021-03-28 18:50:46.042 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 45: Controller status changed to OFFLINE.
2021-03-28 18:50:46.042 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 45: Controller is not online.
2021-03-28 18:50:46.042 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 46: Controller status changed to OFFLINE.
2021-03-28 18:50:46.042 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 46: Controller is not online.
2021-03-28 18:50:46.042 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 47: Controller status changed to OFFLINE.
2021-03-28 18:50:46.042 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 47: Controller is not online.
2021-03-28 18:50:46.042 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 48: Controller status changed to OFFLINE.
2021-03-28 18:50:46.042 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 48: Controller is not online.
2021-03-28 18:50:46.042 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 49: Controller status changed to OFFLINE.
2021-03-28 18:50:46.042 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 49: Controller is not online.
2021-03-28 18:50:46.042 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 127: Controller status changed to OFFLINE.
2021-03-28 18:50:46.074 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 126: Controller status changed to OFFLINE.
2021-03-28 18:50:46.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 126: Controller is not online.
2021-03-28 18:50:46.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 123: Controller status changed to OFFLINE.
2021-03-28 18:50:46.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 123: Controller is not online.
2021-03-28 18:50:46.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 122: Controller status changed to OFFLINE.
2021-03-28 18:50:46.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 122: Controller is not online.
2021-03-28 18:50:46.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 80: Controller status changed to OFFLINE.
2021-03-28 18:50:46.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 80: Controller is not online.
2021-03-28 18:50:46.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 81: Controller status changed to OFFLINE.
2021-03-28 18:50:46.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 81: Controller is not online.
2021-03-28 18:50:46.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 82: Controller status changed to OFFLINE.
2021-03-28 18:50:46.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 82: Controller is not online.
2021-03-28 18:50:46.089 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 128: Controller status changed to OFFLINE.
2021-03-28 18:50:46.105 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 128: Controller is not online.
2021-03-28 18:50:46.105 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Controller status changed to OFFLINE.
2021-03-28 18:50:46.105 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 50: Controller is not online.
2021-03-28 18:50:46.105 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 52: Controller status changed to OFFLINE.
2021-03-28 18:50:46.105 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 52: Controller is not online.
2021-03-28 18:50:46.105 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 55: Controller status changed to OFFLINE.
2021-03-28 18:50:46.105 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 55: Controller is not online.
2021-03-28 18:50:46.105 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 56: Controller status changed to OFFLINE.
2021-03-28 18:50:46.105 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 56: Controller is not online.
2021-03-28 18:50:46.105 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Controller status changed to OFFLINE.
2021-03-28 18:50:46.105 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 57: Controller is not online.
2021-03-28 18:50:46.105 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 58: Controller status changed to OFFLINE.
2021-03-28 18:50:46.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 58: Controller is not online.
2021-03-28 18:50:46.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Controller status changed to OFFLINE.
2021-03-28 18:50:46.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Controller is not online.
2021-03-28 18:50:46.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Controller status changed to OFFLINE.
2021-03-28 18:50:46.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 16: Controller is not online.
2021-03-28 18:50:46.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Controller status changed to OFFLINE.
2021-03-28 18:50:46.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 18: Controller is not online.
2021-03-28 18:50:46.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Controller status changed to OFFLINE.
2021-03-28 18:50:46.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Controller is not online.
2021-03-28 18:50:46.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Controller status changed to OFFLINE.
2021-03-28 18:50:46.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: Controller is not online.
2021-03-28 18:50:46.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Controller status changed to OFFLINE.
2021-03-28 18:50:46.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 33: Controller is not online.
2021-03-28 18:50:46.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 38: Controller status changed to OFFLINE.
2021-03-28 18:50:46.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 38: Controller is not online.
2021-03-28 18:50:46.121 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 41: Controller status changed to OFFLINE.
2021-03-28 18:50:46.011 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Controller status changed to OFFLINE.
2021-03-28 18:50:46.136 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Controller is not online.
2021-03-28 18:50:46.136 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Controller status changed to OFFLINE.
2021-03-28 18:50:46.136 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Controller is not online.
2021-03-28 18:50:46.214 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 127: Controller is not online.
2021-03-28 18:50:46.214 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 41: Controller is not online.
2021-03-28 18:50:50.979 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWave Transaction manager failed to terminate properly, forcing shutdown
2021-03-28 18:50:50.979 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction manager shutdown
2021-03-28 18:50:50.979 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 128: Node Init transaction completed with response null
2021-03-28 18:50:50.979 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 128: Skipping initialization thread, process stopped by controller
2021-03-28 18:50:51.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: sendTransaction exception
java.util.concurrent.ExecutionException: java.lang.InterruptedException
at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:?]
at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?]
at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1205) [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:?]
Caused by: java.lang.InterruptedException
at java.lang.Object.wait(Native Method) ~[?:?]
at java.lang.Object.wait(Object.java:328) ~[?:?]
at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter.call(ZWaveTransactionManager.java:1134) ~[?:?]
at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter.call(ZWaveTransactionManager.java:1) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
at java.lang.Thread.run(Thread.java:834) ~[?:?]
2021-03-28 18:50:51.042 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Node Init transaction completed with response null
2021-03-28 18:50:51.042 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 15: Skipping initialization thread, process stopped by controller
2021-03-28 18:50:50.995 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 50: sendTransaction exception
java.util.concurrent.ExecutionException: java.lang.InterruptedException
at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:?]
at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?]
at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1205) [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:?]
Caused by: java.lang.InterruptedException
at java.lang.Object.wait(Native Method) ~[?:?]
at java.lang.Object.wait(Object.java:328) ~[?:?]
at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter.call(ZWaveTransactionManager.java:1134) ~[?:?]
at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter.call(ZWaveTransactionManager.java:1) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
at java.lang.Thread.run(Thread.java:834) ~[?:?]
2021-03-28 18:50:51.073 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 50: Node Init response (0) null
2021-03-28 18:50:50.995 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 56: sendTransaction exception
java.util.concurrent.ExecutionException: java.lang.InterruptedException
at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:?]
at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?]
at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1205) [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:?]
Caused by: java.lang.InterruptedException
at java.lang.Object.wait(Native Method) ~[?:?]
at java.lang.Object.wait(Object.java:328) ~[?:?]
at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter.call(ZWaveTransactionManager.java:1134) ~[?:?]
at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter.call(ZWaveTransactionManager.java:1) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
at java.lang.Thread.run(Thread.java:834) ~[?:?]
2021-03-28 18:50:51.084 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 56: Node Init response (0) null
2021-03-28 18:50:50.995 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 32: sendTransaction exception
java.util.concurrent.ExecutionException: java.lang.InterruptedException
at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:?]
at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?]
at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1205) [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:?]
Caused by: java.lang.InterruptedException
at java.lang.Object.wait(Native Method) ~[?:?]
at java.lang.Object.wait(Object.java:328) ~[?:?]
at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter.call(ZWaveTransactionManager.java:1134) ~[?:?]
at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager$1TransactionWaiter.call(ZWaveTransactionManager.java:1) ~[?:?]
at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
at java.lang.Thread.run(Thread.java:834) ~[?:?]
2021-03-28 18:50:51.094 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 32: Node Init response (0) null
2021-03-28 18:50:50.995 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 67: sendTransaction exception
java.util.concurrent.ExecutionException: java.lang.InterruptedException
at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:?]
at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?]
at org.openhab.binding.zwave.internal.protocol.ZWaveTransactionManager.sendTransaction(ZWaveTransactionManager.java:1205) [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:?]
Caused by: java.lang.InterruptedException
After that there will happen more I/O errors but the binding won’t report any updates anymore. Here is a debug log of the follow up I/O errors starting at 2021-03-28 18:51:02.217:
This error is thrown by the serial driver when there is some sort of error in the low level routines. I normally blame the OS, but it could be an error with the stick, or the USB system possibly re-arbitrating or something like that - I’m not super sure - sorry.
Thank you very much for analyzing.
I already tried to narrow down these possible causes. I just changed yesterday the computers with one other Z-Wave network in my home (which still did run stable), so the only difference were the 2 sticks. The computer which had the problems in the ground floor is running absolutely stable now in the first floor with the stick from the first floor. But the computer from the first floor, which was running stable all the time, is now throwing exactly the same error with the stick from the ground floor. So I slowly come to the final conclusion that it must be the stick or the network in the ground floor.
However, it can not be the stick hardware as I tried 3 different sticks already. Is must be a problem in the software side of the stick as all the fresh sticks will fail as soon as I put the backups on them. As I even tried 3 different backups (even one from 2 years ago) and all fail, I now start loosing my faith in the backup from Z-Wave sticks…I was really prepared for this problem with lots of backups but it seems that they are worth nothing.
So I will finally switch over to WLAN based Shelly devices for all dimmers, relay switches and roller shutters. The price is only 40% of Z-Wave devices, you do not have to rely on a blackbox network with a single point of failure, the responsiveness is much faster, you have a WEB UI, OTA updates all the time and many more advantages. If this option had been available 2015 already I would never have jumped on the Z-Wave train…now it’s time to modernize the architecture of my smart home. I do not feel like having this again in 4-5 years.
I feel your pain, and wouldn’t disagree too much with a lot of the sentiment in your mail. In this case though I doubt that the problem is ZWave related, but who knows.
ZWave certainly has its issues - much of the protocol is not well thought through, has been poorly extended over the years, and is quite “old”. Wifi systems will however have their own issues - especially as you build up the size of a network, and if you have any battery devices, you will likely have problems there. So each system will have pros and cons and it’s up to each individual to work through their own requirements…
Or how the radio works on that floor. Where is the controller, what is between the controller and nodes? Radio waves are a funny thing… you know… just saying
right…
practical limits of wifi nodes is… I don’t know 10 or 15 nodes before stuff starts dropping off, this is with single consumer grade router, I’m sure better router or multiple APs could do better but… there is a limit.
personally, with all the troubleshooting you’ve done, I knew it wasn’t the host, I knew it wasn’t the stick… I was going to say look for a flakey node, but whatever, glad you found something that works for you
Sure, that is why I only intend to change the flush mounted devices to Shelly like relay swtiches, dimmers and rollershutter controls. I already replaced each failing Z-Wave device in the last 2,5 years with a Shelly an they work great.
My battery sensors will remain Z-Wave and also my thermostats (my wife likes the design…). So I Have one main powered repeater for Z-Wave in each room so the Mesh should work. All the rest goes WLAN.
Well it all worked flawless for over 4 years, so that was probably not the cause.
I do have better routers and already prepared my network mask to address more than 750 devices
This will result in a weak mesh - it may work most of even all of the time, or it may result in a lot of dropped frames since it’s likely there will be minimal meshing. This is why I normally suggest to people to stick with one technology.
