Zwave network fails suddenly

jan_r · July 19, 2019, 10:10pm

Hi all,

I need your help please. I have a z-wave network with 14 nodes which worked pretty fine until recently. All of a sudden the devices don’t react anymore. From the log it seems like they don’t initialize anymore. In HABmin they show as “Node initializing: PING” or "Node initializing: “Request_NIF”. However I can’t make any sense out of it what to do next…
Help would be greatly appreciated!

Here is the log of about 1-2 min after reboot:

2019-07-19 23:31:49.707 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventFactory}={service.id=319, service.bundleid=273, service.scope=bundle, component.name=org.openhab.binding.zwave.event.BindingEventFactory, component.id=205} - org.openhab.binding.zwave
2019-07-19 23:31:49.766 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTED - org.openhab.binding.zwave
2019-07-19 23:31:49.926 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'rrd4j.persist'
2019-07-19 23:31:49.954 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'mapdb.persist'
2019-07-19 23:31:49.989 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'influxdb.persist'
2019-07-19 23:31:50.374 [INFO ] [b.core.service.AbstractActiveService] - FritzBox refresh Service has been started
2019-07-19 23:31:51.191 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.178.50:8080
2019-07-19 23:31:51.193 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.178.50:8443
2019-07-19 23:31:51.292 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2019-07-19 23:31:52.202 [INFO ] [penhab.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2019-07-19 23:31:52.203 [INFO ] [t.mqtt.internal.MqttBrokerConnection] - Starting MQTT broker connection 'mqtt'
2019-07-19 23:31:53.341 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'ntp:ntp:local' to inbox.
2019-07-19 23:31:56.054 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2019-07-19 23:31:56.056 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:4bd824b3.
2019-07-19 23:31:56.058 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 3 hours time.
2019-07-19 23:31:56.100 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port '/dev/ttyACM0'
2019-07-19 23:31:56.130 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=398, service.bundleid=273, service.scope=singleton} - org.openhab.binding.zwave
2019-07-19 23:31:56.133 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=399, service.bundleid=273, service.scope=singleton} - org.openhab.binding.zwave
2019-07-19 23:31:56.133 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=401, service.bundleid=273, service.scope=singleton} - org.openhab.binding.zwave
2019-07-19 23:31:56.133 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=400, service.bundleid=273, service.scope=singleton} - org.openhab.binding.zwave
2019-07-19 23:31:56.146 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=402, service.bundleid=273, service.scope=singleton} - org.openhab.binding.zwave
2019-07-19 23:31:56.233 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:4bd824b3:node9.
2019-07-19 23:31:56.274 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:4bd824b3:node6.
2019-07-19 23:31:56.277 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=404, service.bundleid=273, service.scope=singleton} - org.openhab.binding.zwave
2019-07-19 23:31:56.284 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Channel zwave:device:4bd824b3:node9:switch_dimmer linked - polling started.
2019-07-19 23:31:56.286 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=403, service.bundleid=273, service.scope=singleton} - org.openhab.binding.zwave
2019-07-19 23:31:56.289 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Channel zwave:device:4bd824b3:node6:scene_number linked - polling started.
2019-07-19 23:31:56.289 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Channel zwave:device:4bd824b3:node6:alarm_power linked - polling started.
2019-07-19 23:31:56.290 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Channel zwave:device:4bd824b3:node6:battery-level linked - polling started.
2019-07-19 23:31:56.290 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Channel zwave:device:4bd824b3:node6:scene_number3 linked - polling started.
2019-07-19 23:31:56.292 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Channel zwave:device:4bd824b3:node6:scene_number1 linked - polling started.
2019-07-19 23:31:56.291 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Channel zwave:device:4bd824b3:node6:scene_number4 linked - polling started.
2019-07-19 23:31:56.290 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Channel zwave:device:4bd824b3:node6:scene_number2 linked - polling started.
2019-07-19 23:31:56.324 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:4bd824b3:node7.
2019-07-19 23:31:56.328 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=405, service.bundleid=273, service.scope=singleton} - org.openhab.binding.zwave
2019-07-19 23:31:56.329 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:4bd824b3:node8.
2019-07-19 23:31:56.331 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Channel zwave:device:4bd824b3:node7:switch_binary linked - polling started.
2019-07-19 23:31:56.332 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Channel zwave:device:4bd824b3:node7:sensor_power linked - polling started.
2019-07-19 23:31:56.332 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Channel zwave:device:4bd824b3:node7:meter_watts linked - polling started.
2019-07-19 23:31:56.333 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Channel zwave:device:4bd824b3:node7:meter_kwh linked - polling started.
2019-07-19 23:31:56.334 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Channel zwave:device:4bd824b3:node7:config_decimal_param41 linked - polling started.
2019-07-19 23:31:56.334 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Channel zwave:device:4bd824b3:node7:config_decimal_param42 linked - polling started.
2019-07-19 23:31:56.335 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Channel zwave:device:4bd824b3:node7:alarm_power linked - polling started.
2019-07-19 23:31:56.335 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:4bd824b3:node8:sensor_relhumidity linked - polling started.
2019-07-19 23:31:56.335 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:4bd824b3:node8:sensor_temperature linked - polling started.
2019-07-19 23:31:56.336 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:4bd824b3:node8:sensor_luminance linked - polling started.
2019-07-19 23:31:56.336 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:4bd824b3:node8:sensor_ultraviolet linked - polling started.
2019-07-19 23:31:56.336 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:4bd824b3:node8:alarm_tamper linked - polling started.
2019-07-19 23:31:56.336 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:4bd824b3:node8:alarm_motion linked - polling started.
2019-07-19 23:31:56.337 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:4bd824b3:node8:battery-level linked - polling started.
2019-07-19 23:31:56.338 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Channel zwave:device:4bd824b3:node7:meter_reset linked - polling started.
2019-07-19 23:31:56.344 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=406, service.bundleid=273, service.scope=singleton} - org.openhab.binding.zwave
2019-07-19 23:31:56.364 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
2019-07-19 23:31:56.371 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2019-07-19 23:31:56.372 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
2019-07-19 23:31:56.395 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
2019-07-19 23:31:56.434 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:4bd824b3:node5.
2019-07-19 23:31:56.436 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:4bd824b3:node14.
2019-07-19 23:31:56.437 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:4bd824b3:node3.
2019-07-19 23:31:56.443 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=407, service.bundleid=273, service.scope=singleton} - org.openhab.binding.zwave
2019-07-19 23:31:56.444 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:4bd824b3:node2.
2019-07-19 23:31:56.447 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=408, service.bundleid=273, service.scope=singleton} - org.openhab.binding.zwave
2019-07-19 23:31:56.449 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 03 0A 32 02 21 34 00 00 00 21 00 00 E6 
2019-07-19 23:31:56.449 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:4bd824b3:node4.
2019-07-19 23:31:56.455 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Channel zwave:device:4bd824b3:node5:switch_binary linked - polling started.
2019-07-19 23:31:56.456 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Channel zwave:device:4bd824b3:node5:blinds_control linked - polling started.
2019-07-19 23:31:56.456 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Channel zwave:device:4bd824b3:node5:scene_number linked - polling started.
2019-07-19 23:31:56.457 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Channel zwave:device:4bd824b3:node5:meter_watts linked - polling started.
2019-07-19 23:31:56.456 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Channel zwave:device:4bd824b3:node5:sensor_power linked - polling started.
2019-07-19 23:31:56.459 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=409, service.bundleid=273, service.scope=singleton} - org.openhab.binding.zwave
2019-07-19 23:31:56.459 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Channel zwave:device:4bd824b3:node5:meter_kwh linked - polling started.
2019-07-19 23:31:56.460 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Channel zwave:device:4bd824b3:node5:blinds_shutter linked - polling started.
2019-07-19 23:31:56.460 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Channel zwave:device:4bd824b3:node5:blinds_lamella linked - polling started.
2019-07-19 23:31:56.471 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 03 0A 32 02 21 34 00 00 00 20 00 00 E7 
2019-07-19 23:31:56.474 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=410, service.bundleid=273, service.scope=singleton} - org.openhab.binding.zwave
2019-07-19 23:31:56.478 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Channel zwave:device:4bd824b3:node14:switch_binary2 linked - polling started.
2019-07-19 23:31:56.477 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Channel zwave:device:4bd824b3:node14:switch_binary linked - polling started.
2019-07-19 23:31:56.483 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:4bd824b3:node12.
2019-07-19 23:31:56.477 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Channel zwave:device:4bd824b3:node14:switch_binary1 linked - polling started.
2019-07-19 23:31:56.493 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Channel zwave:device:4bd824b3:node2:alarm_tamper linked - polling started.
2019-07-19 23:31:56.493 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Channel zwave:device:4bd824b3:node2:sensor_door linked - polling started.
2019-07-19 23:31:56.493 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Channel zwave:device:4bd824b3:node2:battery-level linked - polling started.
2019-07-19 23:31:56.500 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Channel zwave:device:4bd824b3:node4:meter_kwh linked - polling started.
2019-07-19 23:31:56.501 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Channel zwave:device:4bd824b3:node4:scene_number linked - polling started.
2019-07-19 23:31:56.504 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 10 03 0A 32 02 21 34 00 00 00 20 00 00 F7 
2019-07-19 23:31:56.501 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Channel zwave:device:4bd824b3:node4:meter_reset linked - polling started.
2019-07-19 23:31:56.504 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Channel zwave:device:4bd824b3:node4:meter_kwh1 linked - polling started.
2019-07-19 23:31:56.504 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Channel zwave:device:4bd824b3:node4:switch_binary1 linked - polling started.
2019-07-19 23:31:56.505 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Channel zwave:device:4bd824b3:node4:switch_binary2 linked - polling started.
2019-07-19 23:31:56.505 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Channel zwave:device:4bd824b3:node4:meter_watts1 linked - polling started.
2019-07-19 23:31:56.506 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Channel zwave:device:4bd824b3:node4:meter_kwh2 linked - polling started.
2019-07-19 23:31:56.506 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Channel zwave:device:4bd824b3:node4:meter_watts2 linked - polling started.
2019-07-19 23:31:56.507 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Channel zwave:device:4bd824b3:node3:switch_binary linked - polling started.
2019-07-19 23:31:56.508 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Channel zwave:device:4bd824b3:node3:scene_number linked - polling started.
2019-07-19 23:31:56.508 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Channel zwave:device:4bd824b3:node3:meter_current linked - polling started.
2019-07-19 23:31:56.508 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Channel zwave:device:4bd824b3:node3:meter_kwh linked - polling started.
2019-07-19 23:31:56.501 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Channel zwave:device:4bd824b3:node4:meter_watts linked - polling started.
2019-07-19 23:31:56.509 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Channel zwave:device:4bd824b3:node4:alarm_general linked - polling started.
2019-07-19 23:31:56.509 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Channel zwave:device:4bd824b3:node3:meter_reset linked - polling started.
2019-07-19 23:31:56.512 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Channel zwave:device:4bd824b3:node12:sensor_door linked - polling started.
2019-07-19 23:31:56.514 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Channel zwave:device:4bd824b3:node12:alarm_burglar linked - polling started.
2019-07-19 23:31:56.515 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Channel zwave:device:4bd824b3:node12:battery-level linked - polling started.
2019-07-19 23:31:56.532 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2019-07-19 23:31:56.533 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2019-07-19 23:31:56.537 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2019-07-19 23:31:56.538 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 23:31:56.544 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:4bd824b3 with scan time of 30
2019-07-19 23:31:56.545 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:4bd824b3
2019-07-19 23:31:56.555 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=411, service.bundleid=273, service.scope=singleton} - org.openhab.binding.zwave
2019-07-19 23:31:56.557 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-19 23:31:56.592 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:4bd824b3:node13.
2019-07-19 23:31:56.599 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:4bd824b3:node13:sensor_binary linked - polling started.
2019-07-19 23:31:56.599 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:4bd824b3:node13:sensor_co linked - polling started.
2019-07-19 23:31:56.602 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:4bd824b3:node13:alarm_burglar linked - polling started.
2019-07-19 23:31:56.602 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:4bd824b3:node13:alarm_system linked - polling started.
2019-07-19 23:31:56.603 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:4bd824b3:node13:battery-level linked - polling started.
2019-07-19 23:31:56.603 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:4bd824b3:node13:alarm_power linked - polling started.
2019-07-19 23:31:56.604 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:4bd824b3:node13:alarm_general linked - polling started.
2019-07-19 23:31:56.602 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:4bd824b3:node13:alarm_heat linked - polling started.
2019-07-19 23:31:56.601 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:4bd824b3:node13:alarm_co linked - polling started.
2019-07-19 23:31:56.600 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:4bd824b3:node13:sensor_temperature linked - polling started.
2019-07-19 23:31:56.610 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:4bd824b3:node11.
2019-07-19 23:31:56.615 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:4bd824b3:node10.
2019-07-19 23:31:56.626 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:sensor_power linked - polling started.
2019-07-19 23:31:56.626 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:switch_dimmer linked - polling started.
2019-07-19 23:31:56.626 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:meter_watts linked - polling started.
2019-07-19 23:31:56.627 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:meter_kwh linked - polling started.
2019-07-19 23:31:56.627 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:color_color linked - polling started.
2019-07-19 23:31:56.627 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:scene_number_param72 linked - polling started.
2019-07-19 23:31:56.628 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:switch_dimmer2 linked - polling started.
2019-07-19 23:31:56.628 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:switch_dimmer4 linked - polling started.
2019-07-19 23:31:56.628 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:switch_dimmer3 linked - polling started.
2019-07-19 23:31:56.629 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:switch_dimmer5 linked - polling started.
2019-07-19 23:31:56.629 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:sensor_power linked - polling started.
2019-07-19 23:31:56.629 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:scene_number linked - polling started.
2019-07-19 23:31:56.630 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:meter_kwh linked - polling started.
2019-07-19 23:31:56.631 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:meter_watts linked - polling started.
2019-07-19 23:31:56.631 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:meter_reset linked - polling started.
2019-07-19 23:31:56.632 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:config_decimal_param19 linked - polling started.
2019-07-19 23:31:56.632 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:alarm_heat linked - polling started.
2019-07-19 23:31:56.632 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:alarm_power linked - polling started.
2019-07-19 23:31:56.633 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:alarm_system linked - polling started.
2019-07-19 23:31:56.633 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:switch_dimmer1 linked - polling started.
2019-07-19 23:31:56.633 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:sensor_power1 linked - polling started.
2019-07-19 23:31:56.634 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:meter_watts1 linked - polling started.
2019-07-19 23:31:56.634 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:alarm_heat1 linked - polling started.
2019-07-19 23:31:56.635 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:alarm_power1 linked - polling started.
2019-07-19 23:31:56.635 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:alarm_system1 linked - polling started.
2019-07-19 23:31:56.635 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:switch_dimmer2 linked - polling started.
2019-07-19 23:31:56.634 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:meter_kwh1 linked - polling started.
2019-07-19 23:31:59.061 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'daytime.rules'
2019-07-19 23:31:59.273 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'haus.sitemap'
2019-07-19 23:31:59.406 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Channel zwave:device:4bd824b3:node4:switch_binary1 linked - polling started.
2019-07-19 23:31:59.416 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: Channel zwave:device:4bd824b3:node4:switch_binary2 linked - polling started.
2019-07-19 23:31:59.419 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Channel zwave:device:4bd824b3:node3:switch_binary linked - polling started.
2019-07-19 23:31:59.420 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Channel zwave:device:4bd824b3:node5:blinds_control linked - polling started.
2019-07-19 23:31:59.421 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: Channel zwave:device:4bd824b3:node7:switch_binary linked - polling started.
2019-07-19 23:31:59.421 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 10: Channel zwave:device:4bd824b3:node10:switch_dimmer1 linked - polling started.
2019-07-19 23:31:59.422 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: Channel zwave:device:4bd824b3:node9:switch_dimmer linked - polling started.
2019-07-19 23:31:59.423 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:switch_dimmer linked - polling started.
2019-07-19 23:31:59.423 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:color_color linked - polling started.
2019-07-19 23:31:59.424 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:switch_dimmer5 linked - polling started.
2019-07-19 23:31:59.425 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:switch_dimmer2 linked - polling started.
2019-07-19 23:31:59.425 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:switch_dimmer3 linked - polling started.
2019-07-19 23:31:59.427 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:4bd824b3:node13:sensor_co linked - polling started.
2019-07-19 23:31:59.434 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:4bd824b3:node13:alarm_co linked - polling started.
2019-07-19 23:31:59.426 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:scene_number_param72 linked - polling started.
2019-07-19 23:31:59.426 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: Channel zwave:device:4bd824b3:node11:switch_dimmer4 linked - polling started.
2019-07-19 23:31:59.446 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:4bd824b3:node13:sensor_temperature linked - polling started.
2019-07-19 23:31:59.448 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:4bd824b3:node13:alarm_heat linked - polling started.
2019-07-19 23:31:59.452 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: Channel zwave:device:4bd824b3:node13:battery-level linked - polling started.
2019-07-19 23:31:59.453 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Channel zwave:device:4bd824b3:node2:battery-level linked - polling started.
2019-07-19 23:31:59.452 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Channel zwave:device:4bd824b3:node2:sensor_door linked - polling started.
2019-07-19 23:31:59.458 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: Channel zwave:device:4bd824b3:node6:scene_number linked - polling started.
2019-07-19 23:31:59.469 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:4bd824b3:node8:sensor_temperature linked - polling started.
2019-07-19 23:31:59.470 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: Channel zwave:device:4bd824b3:node8:sensor_relhumidity linked - polling started.
2019-07-19 23:31:59.484 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Channel zwave:device:4bd824b3:node12:sensor_door linked - polling started.
2019-07-19 23:31:59.485 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Channel zwave:device:4bd824b3:node14:switch_binary1 linked - polling started.
2019-07-19 23:31:59.539 [DEBUG] [.ZWaveController$InitializeDelayTask] - Initialising network
2019-07-19 23:31:59.568 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 0 to queue - size 1
2019-07-19 23:31:59.569 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-19 23:31:59.571 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9 
2019-07-19 23:31:59.572 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2019-07-19 23:31:59.574 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-07-19 23:31:59.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 23:31:59.577 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 23:31:59.577 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 33 2E 39 35 00 01 99 
2019-07-19 23:31:59.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-07-19 23:31:59.578 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-07-19 23:31:59.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 23:31:59.581 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-19 23:31:59.582 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.582 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 33 2E 39 35 00 01 
2019-07-19 23:31:59.584 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 23:31:59.585 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 33 2E 39 35 00 01 
2019-07-19 23:31:59.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-07-19 23:31:59.587 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.588 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 33 2E 39 35 00 01 
2019-07-19 23:31:59.592 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 1 to queue - size 1
2019-07-19 23:31:59.593 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 23:31:59.601 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 2 to queue - size 2
2019-07-19 23:31:59.602 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 23:31:59.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 3 to queue - size 3
2019-07-19 23:31:59.612 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 23:31:59.622 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Get SUC NodeID
2019-07-19 23:31:59.623 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 4 to queue - size 4
2019-07-19 23:31:59.624 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 23:31:59.634 [DEBUG] [serialmessage.GetVersionMessageClass] - Got MessageGetVersion response. Version=Z-Wave 3.95, Library Type=1
2019-07-19 23:31:59.635 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 0: Transaction COMPLETED
2019-07-19 23:31:59.637 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 54ms
2019-07-19 23:31:59.638 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 0: Transaction completed
2019-07-19 23:31:59.639 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:0 DONE
2019-07-19 23:31:59.652 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 23:31:59.653 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-19 23:31:59.655 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 20 DC 
2019-07-19 23:31:59.656 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2019-07-19 23:31:59.657 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-07-19 23:31:59.657 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-19 23:31:59.660 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.661 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 23:31:59.663 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 01 20 D0 98 9A 87 01 82 
2019-07-19 23:31:59.664 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 23:31:59.665 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.666 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-07-19 23:31:59.668 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 23:31:59.669 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=D0 98 9A 87 01 
2019-07-19 23:31:59.671 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 23:31:59.672 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=D0 98 9A 87 01 
2019-07-19 23:31:59.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.675 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-07-19 23:31:59.678 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.683 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=D0 98 9A 87 01 
2019-07-19 23:31:59.685 [DEBUG] [erialmessage.MemoryGetIdMessageClass] - Got MessageMemoryGetId response. Home id = 0xd0989a87, Controller Node id = 1
2019-07-19 23:31:59.686 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1: Transaction COMPLETED
2019-07-19 23:31:59.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 29ms
2019-07-19 23:31:59.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 1: Transaction completed
2019-07-19 23:31:59.694 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:1 DONE
2019-07-19 23:31:59.696 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 23:31:59.699 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-19 23:31:59.700 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB 
2019-07-19 23:31:59.707 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2019-07-19 23:31:59.708 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-07-19 23:31:59.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 23:31:59.708 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-19 23:31:59.715 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.715 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 2B 01 07 01 00 00 86 00 01 00 5A FE 81 FF 88 4F 1F 00 00 FB 9F 7D A0 67 00 00 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 60 00 00 FB 
2019-07-19 23:31:59.716 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 23:31:59.716 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.719 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-07-19 23:31:59.719 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=01 00 00 86 00 01 00 5A FE 81 FF 88 4F 1F 00 00 FB 9F 7D A0 67 00 00 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 60 00 00 
2019-07-19 23:31:59.719 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 23:31:59.720 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 23:31:59.727 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=01 00 00 86 00 01 00 5A FE 81 FF 88 4F 1F 00 00 FB 9F 7D A0 67 00 00 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 60 00 00 
2019-07-19 23:31:59.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.729 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-07-19 23:31:59.735 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.737 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=01 00 00 86 00 01 00 5A FE 81 FF 88 4F 1F 00 00 FB 9F 7D A0 67 00 00 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 60 00 00 
2019-07-19 23:31:59.740 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - API Version    = 1.0
2019-07-19 23:31:59.741 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Manufacture ID = 0x86
2019-07-19 23:31:59.745 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Device Type    = 0x1
2019-07-19 23:31:59.746 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Device ID      = 0x5a
2019-07-19 23:31:59.747 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 2: Transaction COMPLETED
2019-07-19 23:31:59.749 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 5 to queue - size 3
2019-07-19 23:31:59.752 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 23:31:59.753 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 38ms
2019-07-19 23:31:59.754 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 2: Transaction completed
2019-07-19 23:31:59.754 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:2 DONE
2019-07-19 23:31:59.755 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 23:31:59.756 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-19 23:31:59.757 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 06 96 0F 65 
2019-07-19 23:31:59.758 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2019-07-19 23:31:59.759 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-07-19 23:31:59.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 23:31:59.761 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 01 06 96 0F 64 
2019-07-19 23:31:59.759 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-19 23:31:59.762 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.763 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 1<>127 : Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 
2019-07-19 23:31:59.764 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (1): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 23:31:59.765 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.766 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-07-19 23:31:59.767 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 
2019-07-19 23:31:59.768 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-07-19 23:31:59.769 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 3: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.771 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiSetTimeouts[6], type=Response[1], dest=255, callback=0, payload=96 0F 
2019-07-19 23:31:59.775 [DEBUG] [age.SerialApiSetTimeoutsMessageClass] - Got SerialApiSetTimeouts response. ACK=150, BYTE=15
2019-07-19 23:31:59.776 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 3: Transaction COMPLETED
2019-07-19 23:31:59.779 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 17ms
2019-07-19 23:31:59.781 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 3: Transaction completed
2019-07-19 23:31:59.790 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:3 DONE
2019-07-19 23:31:59.797 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 23:31:59.801 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-19 23:31:59.802 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 56 AA 
2019-07-19 23:31:59.803 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2019-07-19 23:31:59.804 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-19 23:31:59.805 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-07-19 23:31:59.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 23:31:59.805 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.806 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 56 01 AD 
2019-07-19 23:31:59.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=01 
2019-07-19 23:31:59.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 23:31:59.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.809 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-07-19 23:31:59.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=01 
2019-07-19 23:31:59.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.811 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-07-19 23:31:59.812 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 4: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-07-19 23:31:59.813 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetSucNodeId[86], type=Response[1], dest=255, callback=0, payload=01 
2019-07-19 23:31:59.813 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Got SUC NodeID response.
2019-07-19 23:31:59.814 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - NODE 1: Node is SUC.
2019-07-19 23:31:59.815 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 4: Transaction COMPLETED
2019-07-19 23:31:59.816 [DEBUG] [etControllerCapabilitiesMessageClass] - Creating GET_CONTROLLER_CAPABILITIES message
2019-07-19 23:31:59.817 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 6 to queue - size 2
2019-07-19 23:31:59.818 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 23:31:59.818 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 13ms
2019-07-19 23:31:59.819 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 4: Transaction completed
2019-07-19 23:31:59.820 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:4 DONE
2019-07-19 23:31:59.821 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 23:31:59.821 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

Bruce_Osborne · July 19, 2019, 10:19pm

@chris or @sihui any ideas?

What version of OH & binding?

NicGray · July 19, 2019, 10:24pm

Generally after a reboot zwave devices can take a while to show up healthy as they might be battery operated and only respond to poll after several hours.

As a first step I would enable zwave trace log (into a seperate file for your sanity. I leave this on permanently as you can deep dive or tail when something is weird)

There are instructions within the forums on how to do this.

jan_r · July 19, 2019, 10:26pm

Openhab is 2.4.0
Zwave binding is binding-zwave - 2.4.0, too
Zwave controller is an aeotec gen5 usb stick

5iver · July 19, 2019, 11:15pm

There’s no need for trace… debug is sufficient unless you are trying to track down low level communications issues. Don’t leave even debug logging on for extended periods unless you don’t care about the life of your drive, especially if you are using an SD card.

chris · July 20, 2019, 8:39am

I would suggest to use DEBUG logging - not TRACE logging as this will just swamp the logs making it harder to read. TRACE is only required in very low level issue tracking.

jan_r · July 20, 2019, 11:41am

Ok, so no TRACE. The log file above was made with DEBUG mode. Any hints on what I should look into?

chris · July 20, 2019, 12:12pm

Please provide a debug log file that shows the issue and I will be happy to look at it. The log you provided above is 3 seconds long and only shows the first couple of interactions with the controller - everything is working fine.

jan_r · July 21, 2019, 8:03pm

Finally made it: here is a link to PasteFS containing a separate log for the first 10 min. Thanks for looking into it.

jan_r · July 22, 2019, 7:43pm

Hi @chris , could you please have a look the link to PasteFS containing a separate log for the first 10 min. I don’t know how to solve this and my wife starts moaning about the dark living room. Hence your help is desperately needed… Thanks in advance
Jan

chris · July 22, 2019, 9:04pm

I can’t find any way to download this file. It is obviously large, and as a text file it’s taking a long time to load in the browser, but I can’t select all the text, and I can’t download it.

Can you maybe zip it up? Or maybe there’s a way to download it rather than to view it? Other sites often have a download button, but I don’t see that here.

Bruce_Osborne · July 22, 2019, 9:54pm

I copied & zipped. Here is a dropbox link.

jan_r · July 23, 2019, 6:02pm

@Bruce_Osborne: thanks a lot!
@chris : did you have any chance to look at the zip file? Thanks!

chris · July 23, 2019, 6:31pm

One thing I would look at is node 3 - it is clearly swamping the network and this will cause problems -:

We see that a lot of messages are rejected when this happens -:

As I understand it, the rejection is caused by the controller running out of buffers - probably caused by node 3 sending a lot of messages in a very short time.

This is happening an aweful log in your log, so I would suggest first to solve this problem. Possibly it’s caused by this device not receiving ACKs from other devices os it’s resending, or it may be caused by incorrect association configuration (eg setting multiple associations will cause multiple messages to be sent by the device).

My guess is the device is not receiving the acks properly and I would suggest to reset this device and see if it helps.

jan_r · July 23, 2019, 7:59pm

Awesome! I unplugged node 3 and we don’t have to sit in the dark anymore Thanks a lot, @chris!