Zwave bridge wont go online

Thanks Andrew -

I updated the system using the openhabian-config tool to the latest SNAPSHOT … I ended up with openHAB 3.4.0 Build #3029. The above link says build 3.3.0 but is that a typo?

Anyway, after updating and restarting, I got a slew of Zigbee errors (see below) … will reboot to see if it repeats. Rebooted … system is slowly coming up … it takes about 30 minutes for the Zigbee devices to all come ONLINE (I have ~50 devices), then the ZWave devices follow … so far so good. Ok, all the zigbee devices came up but the Zwave devices are all in Error:Bridge … same as before :frowning: I had high hopes! Zwave DEBUG was not on so I dont know if its the same (seems likely)

I’ll take another stab at it tomorrow with DEBUG enabled.

==> /var/log/openhab/openhab.log <==
2022-08-02 20:28:38.836 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
	at org.openhab.binding.zigbee.internal.converter.ZigBeeConverterMeteringSummationDelivered.initializeDevice(ZigBeeConverterMeteringSummationDelivered.java:76) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:260) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	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:829) [?:?]
2022-08-02 20:28:38.854 [ERROR] [ng.zigbee.handler.ZigBeeThingHandler] - null: Exception creating channels 
java.lang.NullPointerException: null
	at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:936) ~[?:?]
	at com.zsmartsystems.zigbee.ZigBeeNetworkManager.getNode(ZigBeeNetworkManager.java:1646) ~[bundleFile:?]
	at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.getNode(ZigBeeCoordinatorHandler.java:992) ~[bundleFile:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.createZigBeeChannelConverter(ZigBeeThingHandler.java:525) ~[bundleFile:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:385) [bundleFile:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:227) [bundleFile:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) [bundleFile:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
	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:829) [?:?]
2022-08-02 20:28:38.833 [ERROR] [ng.zigbee.handler.ZigBeeThingHandler] - null: Exception getting binding table 
java.util.concurrent.ExecutionException: java.lang.NullPointerException
	at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:?]
	at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:445) [bundleFile:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:227) [bundleFile:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) [bundleFile:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
	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:829) [?:?]
Caused by: java.lang.NullPointerException
	at com.zsmartsystems.zigbee.ZigBeeNode$1.call(ZigBeeNode.java:465) ~[?:?]
	at com.zsmartsystems.zigbee.ZigBeeNode$1.call(ZigBeeNode.java:454) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	... 1 more
2022-08-02 20:28:38.818 [ERROR] [ng.zigbee.handler.ZigBeeThingHandler] - null: Exception getting binding table 
java.util.concurrent.ExecutionException: java.lang.NullPointerException
	at java.util.concurrent.FutureTask.report(FutureTask.java:122) ~[?:?]
	at java.util.concurrent.FutureTask.get(FutureTask.java:191) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:445) [bundleFile:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:227) [bundleFile:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) [bundleFile:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
	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:829) [?:?]
Caused by: java.lang.NullPointerException
	at com.zsmartsystems.zigbee.ZigBeeNode$1.call(ZigBeeNode.java:465) ~[?:?]
	at com.zsmartsystems.zigbee.ZigBeeNode$1.call(ZigBeeNode.java:454) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	... 1 more
2022-08-02 20:28:38.836 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
	at org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchOnoff.initializeDevice(ZigBeeConverterSwitchOnoff.java:105) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:260) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	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:829) [?:?]
2022-08-02 20:28:38.828 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
	at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.addPropertiesFromBasicCluster(ZigBeeNodePropertyDiscoverer.java:157) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.getProperties(ZigBeeNodePropertyDiscoverer.java:109) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:222) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	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:829) [?:?]
2022-08-02 20:28:38.836 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
	at com.zsmartsystems.zigbee.zcl.ZclCluster.readSync(ZclCluster.java:1727) ~[?:?]
	at com.zsmartsystems.zigbee.zcl.clusters.ZclBasicCluster.getStackVersion(ZclBasicCluster.java:393) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.addPropertiesFromBasicCluster(ZigBeeNodePropertyDiscoverer.java:204) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.getProperties(ZigBeeNodePropertyDiscoverer.java:109) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:222) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	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:829) [?:?]
2022-08-02 20:28:38.934 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
	at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.addPropertiesFromBasicCluster(ZigBeeNodePropertyDiscoverer.java:157) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.getProperties(ZigBeeNodePropertyDiscoverer.java:109) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:222) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	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:829) [?:?]
2022-08-02 20:28:38.825 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
	at com.zsmartsystems.zigbee.zcl.ZclCluster.readSync(ZclCluster.java:1727) ~[?:?]
	at com.zsmartsystems.zigbee.zcl.clusters.ZclBasicCluster.getDateCode(ZclBasicCluster.java:673) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.addPropertiesFromBasicCluster(ZigBeeNodePropertyDiscoverer.java:222) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.getProperties(ZigBeeNodePropertyDiscoverer.java:109) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:222) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	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:829) [?:?]
2022-08-02 20:28:38.900 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
	at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:936) ~[?:?]
	at com.zsmartsystems.zigbee.ZigBeeNetworkManager.getNode(ZigBeeNetworkManager.java:1646) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.getNode(ZigBeeCoordinatorHandler.java:992) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:238) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:227) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	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:829) [?:?]
2022-08-02 20:28:38.909 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
	at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:936) ~[?:?]
	at com.zsmartsystems.zigbee.ZigBeeNetworkManager.getNode(ZigBeeNetworkManager.java:1646) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.getNode(ZigBeeCoordinatorHandler.java:992) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:238) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:227) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	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:829) [?:?]
2022-08-02 20:28:38.794 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
	at java.util.concurrent.ConcurrentHashMap.get(ConcurrentHashMap.java:936) ~[?:?]
	at com.zsmartsystems.zigbee.ZigBeeNetworkManager.getNode(ZigBeeNetworkManager.java:1646) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeCoordinatorHandler.getNodeEndpoints(ZigBeeCoordinatorHandler.java:885) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler.doNodeInitialisation(ZigBeeThingHandler.java:266) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:227) ~[?:?]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$1.call(ZigBeeThingHandler.java:1) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	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:829) [?:?]
2022-08-02 20:28:38.949 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
	at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.addPropertiesFromBasicCluster(ZigBeeNodePropertyDiscoverer.java:157) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.getProperties(ZigBeeNodePropertyDiscoverer.java:109) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:222) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	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:829) [?:?]
2022-08-02 20:28:38.951 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
	at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.addPropertiesFromBasicCluster(ZigBeeNodePropertyDiscoverer.java:157) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.getProperties(ZigBeeNodePropertyDiscoverer.java:109) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:222) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	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:829) [?:?]
2022-08-02 20:28:38.958 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.NullPointerException: null
	at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.addPropertiesFromBasicCluster(ZigBeeNodePropertyDiscoverer.java:157) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeNodePropertyDiscoverer.getProperties(ZigBeeNodePropertyDiscoverer.java:109) ~[?:?]
	at org.openhab.binding.zigbee.discovery.ZigBeeDiscoveryService$2.run(ZigBeeDiscoveryService.java:222) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	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:829) [?:?]

Done.

Well, I restarted the system with Zwave DEBUG enabled … and it shows the exact same symptom: Zwave hung up after connecting to the serial port:

2022-08-03 06:35:20.753 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Controller handler not found. Cannot handle command without ZWave controller.
2022-08-03 06:35:56.158 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Command received zwave:device:0d28f614c7:node10:thermostat_setpoint_heating --> 58 °F [QuantityType]
2022-08-03 06:35:56.159 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Controller handler not found. Cannot handle command without ZWave controller.
2022-08-03 07:02:21.029 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyUSB0'
2022-08-03 07:10:58.868 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:0d28f614c7:node8:lock_door --> ON [OnOffType]
2022-08-03 07:10:58.870 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Controller handler not found. Cannot handle command without ZWave controller.

So, looking for other suggestions that might be causing this intermittent but very repeatable problem.

No solution, but what looks odd is the timing for this

There are three INFO level Zwave binding messages on startup

> 2021-07-28 10:57:17.006 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
> 2021-07-28 10:57:22.260 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
> 2021-07-28 10:57:22.264 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

and the Connecting to serial port ‘/dev/ttyxxxx’ normally occurs between the first and the second INFO or about 5 seconds. I do not see the first INFO in your posted log, but the Connection appears 27 minutes later??.

I found a debug startup from someone else I had on my machine. Note timing of Connection… and the three INFO logs:

> 2021-12-05 19:57:13.106 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
> 2021-12-05 19:57:13.483 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
> 2021-12-05 19:57:13.487 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:c0f0908e.
> 2021-12-05 19:57:13.707 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node24.
> 2021-12-05 19:57:13.718 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node13.
> 2021-12-05 19:57:13.739 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node40.
> 2021-12-05 19:57:13.744 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node23.
> 2021-12-05 19:57:13.764 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node11.
> 2021-12-05 19:57:13.802 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node14.
> 2021-12-05 19:57:13.816 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node37.
> 2021-12-05 19:57:13.833 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node16.
> 2021-12-05 19:57:13.849 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node27.
> 2021-12-05 19:57:13.851 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node33.
> 2021-12-05 19:57:13.880 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node6.
> 2021-12-05 19:57:13.894 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:c0f0908e:node7.
> 2021-12-05 19:57:18.507 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyAMA0'
> 2021-12-05 19:57:18.523 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
> 2021-12-05 19:57:18.535 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
> 2021-12-05 19:57:18.535 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
> 2021-12-05 19:57:18.538 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
> 2021-12-05 19:57:18.627 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
> 2021-12-05 19:57:18.627 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
> 2021-12-05 19:57:18.630 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
> 2021-12-05 19:57:18.630 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

Edit: Found another example (edited just for the controller items)

> 2022-08-02 11:34:08.239 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:71512f5b78 with scan time of 60
> 2022-08-02 11:34:08.260 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:71512f5b78
> 2022-08-02 11:34:08.264 [INFO ] [zwave.handler.ZWaveControllerHandler] - Attempting to add listener when controller is null
> 2022-08-02 11:34:08.659 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
> 2022-08-02 11:34:08.662 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:71512f5b78.
> 2022-08-02 11:34:13.724 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
> 2022-08-02 11:34:13.766 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
> 2022-08-02 11:34:13.779 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
> 2022-08-02 11:34:13.782 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
> 2022-08-02 11:34:13.784 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
> 2022-08-02 11:34:13.866 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
> 2022-08-02 11:34:13.866 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
> 2022-08-02 11:34:13.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
> 2022-08-02 11:34:13.868 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.

Again about 5 seconds

Yes the whole process of Zigbee and then Zwave takes 30-45 minutes to complete … something that is unacceptable but I have not found a solution for. I my case it seems that the Zwave doesn’t attempt to open the serial port until near the end of the 50 Zigbee devices coming ONLINE. I have no idea why.

FYI - I found in the Github issue the exact scenario I am having. It was purported to be fixed, but clearly it has not (perhaps there are multiple instantiations of the serial driver issue) … anyway, I’ve logged my issue on Github with the relevant log parts.

See: Serial ports getting blocked after some re-connecting · Issue #1842 · openhab/openhab-core · GitHub

I can only wish for this :slight_smile:

Do some people have separate Zwave and Zigbee sticks? Is there an inference issue with doing that or will that cause more problems than you have already :wink:?

I’ve considered that … but this is a fairly popular stick … I could disable the Zwave to see if affects zigbee (sort of doubt it would have that dramatic effect, but you never know)