Zwave - Controller handler not found after reboot

Things were working great for a couple of months but the power flickers and the server rebooted. Now I can’t get the zwave controller working, I’ve tried reboots, shutdowns and reinstalling the binding.

2017-07-07 08:48:20.015 [DEBUG] [inding.zwave.internal.ZWaveActivator] - Z-Wave binding started. Version 2.1.0.201705011011
2017-07-07 08:48:20.016 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTED - org.openhab.binding.zwave
2017-07-07 08:48:20.049 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventFactory}={component.name=org.openhab.binding.zwave.event.BindingEventFactory, component.id=197, service.id=334, service.bundleid=221, service.scope=bundle} - org.openhab.binding.zwave
2017-07-07 08:48:20.051 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={component.name=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, component.id=198, service.id=335, service.bundleid=221, service.scope=bundle} - org.openhab.binding.zwave
2017-07-07 08:48:20.091 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigOptionProvider, org.eclipse.smarthome.config.core.ConfigDescriptionProvider}={component.name=org.openhab.binding.zwave.ConfigDescription, component.id=200, service.id=336, service.bundleid=221, service.scope=bundle} - org.openhab.binding.zwave
2017-07-07 08:48:20.233 [INFO ] [ding.astro.handler.AstroThingHandler] - Scheduled astro job-daily-sun at midnight for thing astro:sun:2f38b65e
2017-07-07 08:48:20.888 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2017-07-07 08:48:20.889 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller.
2017-07-07 08:48:20.893 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyUSB0'
2017-07-07 08:48:20.913 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=339, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:20.913 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=341, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:20.914 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=343, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:20.917 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=340, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:20.918 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=342, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:20.929 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=344, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:20.933 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=345, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:20.936 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=346, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:20.947 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=347, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:20.949 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=348, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:20.954 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=349, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:20.965 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=350, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:20.972 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=351, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:20.980 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=352, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:20.981 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
2017-07-07 08:48:20.982 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2017-07-07 08:48:20.983 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
2017-07-07 08:48:20.983 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
2017-07-07 08:48:20.989 [INFO ] [mmandclass.ZWaveSecurityCommandClass] - Update networkKey
2017-07-07 08:48:20.996 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=353, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:20.998 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=354, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:20.999 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2017-07-07 08:48:20.999 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2017-07-07 08:48:21.003 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-07-07 08:48:21.004 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-07-07 08:48:21.013 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Starting ZWave thread: Send
2017-07-07 08:48:21.017 [DEBUG] [ve.internal.protocol.ZWaveController] - Starting ZWave thread: Input
2017-07-07 08:48:21.018 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Activating ZWave discovery service for zwave:serial_zstick:c7a03d10
2017-07-07 08:48:21.019 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=355, service.bundleid=221, service.scope=singleton} - org.openhab.binding.zwave
2017-07-07 08:48:21.020 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-07-07 08:48:21.021 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-07-07 08:48:21.021 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-07-07 08:48:21.021 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-07-07 08:48:21.022 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-07-07 08:48:21.022 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Command received zwave:device:c7a03d10:node21:sensor_door --> REFRESH
2017-07-07 08:48:21.022 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.022 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-07-07 08:48:21.023 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-07-07 08:48:21.023 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-07-07 08:48:21.024 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-07-07 08:48:21.024 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-07-07 08:48:21.025 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-07-07 08:48:21.025 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-07-07 08:48:21.026 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-07-07 08:48:21.026 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler.
2017-07-07 08:48:21.028 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Command received zwave:device:c7a03d10:node6:switch_dimmer --> REFRESH
2017-07-07 08:48:21.028 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.028 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Command received zwave:device:c7a03d10:node10:sensor_door --> REFRESH
2017-07-07 08:48:21.028 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.029 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Command received zwave:device:c7a03d10:node8:switch_binary --> REFRESH
2017-07-07 08:48:21.029 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.031 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Command received zwave:device:c7a03d10:node5:switch_dimmer --> REFRESH
2017-07-07 08:48:21.032 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Command received zwave:device:c7a03d10:node12:sensor_door --> REFRESH
2017-07-07 08:48:21.032 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.032 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.033 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 20: Command received zwave:device:c7a03d10:node20:switch_dimmer --> REFRESH
2017-07-07 08:48:21.033 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.034 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Command received zwave:device:c7a03d10:node7:switch_binary --> REFRESH
2017-07-07 08:48:21.034 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.034 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Command received zwave:device:c7a03d10:node7:scene_number --> REFRESH
2017-07-07 08:48:21.035 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.036 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Command received zwave:device:c7a03d10:node3:switch_binary --> REFRESH
2017-07-07 08:48:21.036 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.037 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Command received zwave:device:c7a03d10:node4:switch_binary --> REFRESH
2017-07-07 08:48:21.037 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.038 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Command received zwave:device:c7a03d10:node4:scene_number --> REFRESH
2017-07-07 08:48:21.038 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.039 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Command received zwave:device:c7a03d10:node2:switch_binary --> REFRESH
2017-07-07 08:48:21.040 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.041 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 19: Command received zwave:device:c7a03d10:node19:switch_binary --> REFRESH
2017-07-07 08:48:21.042 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.043 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 15: Command received zwave:device:c7a03d10:node15:sensor_door --> REFRESH
2017-07-07 08:48:21.043 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.045 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Command received zwave:device:c7a03d10:node11:sensor_binary --> REFRESH
2017-07-07 08:48:21.045 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.045 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Command received zwave:device:c7a03d10:node11:sensor_temperature --> REFRESH
2017-07-07 08:48:21.046 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.047 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Command received zwave:device:c7a03d10:node13:sensor_binary --> REFRESH
2017-07-07 08:48:21.047 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.048 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Command received zwave:device:c7a03d10:node13:sensor_luminance --> REFRESH
2017-07-07 08:48:21.048 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.048 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Command received zwave:device:c7a03d10:node13:sensor_relhumidity --> REFRESH
2017-07-07 08:48:21.049 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.049 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Command received zwave:device:c7a03d10:node13:sensor_temperature --> REFRESH
2017-07-07 08:48:21.050 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:21.051 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Command received zwave:device:c7a03d10:node14:sensor_binary --> REFRESH
2017-07-07 08:48:21.051 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Controller handler not found. Cannot handle command without ZWave controller.
2017-07-07 08:48:22.368 [INFO ] [ternal.scheduler.WeatherJobScheduler] - Starting and scheduling weatherJob-melrose with interval of 15 minutes
2017-07-07 08:48:24.000 [DEBUG] [.ZWaveController$InitializeDelayTask] - Initialising network
2017-07-07 08:48:24.010 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-07-07 08:48:24.010 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-07-07 08:48:24.011 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9
2017-07-07 08:48:24.012 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-07-07 08:48:24.012 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9
2017-07-07 08:48:24.015 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2017-07-07 08:48:24.017 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
2017-07-07 08:48:24.018 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Get SUC NodeID
2017-07-07 08:48:24.020 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 4. Queue={}
2017-07-07 08:48:25.015 [INFO ] [.astro.internal.job.AbstractDailyJob] - Scheduled astro event-jobs for thing astro:sun:2f38b65e
2017-07-07 08:48:29.017 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2017-07-07 08:48:29.018 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 5. Queue={}
2017-07-07 08:48:29.018 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 4
2017-07-07 08:48:29.018 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9
2017-07-07 08:48:29.019 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9

There’s no data being received from the dongle, so either the port changed name following the reboot, or the controller has a problem (or there’s some other serial port issue).

1 Like