[SOLVED] Z-Wave devices remain unknown after update

[phate (David Schulz)]

After having updated my Z-Wave binding onto 2.4, I’m not able to control my devices anymore. I then found the thread by @chris informing about the necessity to remove all items and then add them via the inbox once again and I did that, first trying to keep my controller as it was. This didn’t resolve it for me, so I also removed the controller (and all other Z-Wave things as well), uninstalled the binding, restarted OH service, installed the binding again. The controller is found and after having set the serial port, also the other nodes are detected. Nevertheless, all things remain unknown:

I’m using a range of different Fibaro products such as rollershutters, a multisensor, door/window sensors and switchable wall plugs that had all been working fine before. In addition, I’m also using a heater thermostat by Danfoss (LC-13). As you can see, it’s wired as well as battery powered devices, so I would at least expect the wired ones to be properly recognized rather quickly.

I’ve now also activated debug logging before adding the things from the inbox. As you can see from these two logs about the thermostat (Node 14), it appears to be properly addressed and also messages are flying round here:

2019-01-02 13:33:18.139 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:1d1f009a:node14.
2019-01-02 13:33:18.140 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: MANUFACTURER not set
2019-01-02 13:33:18.141 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Controller status changed to ONLINE.
2019-01-02 13:33:18.141 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Controller is ONLINE. Starting device initialisation.
2019-01-02 13:33:18.146 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Updating node properties.
2019-01-02 13:33:18.149 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Updating node properties. MAN=2147483647
2019-01-02 13:33:18.149 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Properties synchronised
2019-01-02 13:33:18.153 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2019-01-02 13:33:18.153 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Initialising Thing Node...
2019-01-02 13:33:18.153 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Polling intialised at 1800 seconds - start in 545400 milliseconds.
2019-01-02 13:33:18.153 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Device initialisation complete.

after waking up device:

2019-01-02 14:05:54.375 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 14: Application update request. Node information received. Transaction null
2019-01-02 14:05:54.376 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Creating new instance of command class COMMAND_CLASS_BATTERY
2019-01-02 14:05:54.376 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Command class COMMAND_CLASS_BATTERY, endpoint 0 created
2019-01-02 14:05:54.376 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 14: Application update is adding command class COMMAND_CLASS_BATTERY.
2019-01-02 14:05:54.377 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Adding command class COMMAND_CLASS_BATTERY to the list of supported command classes.
2019-01-02 14:05:54.377 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Creating new instance of command class COMMAND_CLASS_CLIMATE_CONTROL_SCHEDULE
2019-01-02 14:05:54.378 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Command class COMMAND_CLASS_CLIMATE_CONTROL_SCHEDULE, endpoint 0 created
2019-01-02 14:05:54.378 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 14: Application update is adding command class COMMAND_CLASS_CLIMATE_CONTROL_SCHEDULE.
2019-01-02 14:05:54.378 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Adding command class COMMAND_CLASS_CLIMATE_CONTROL_SCHEDULE to the list of supported command classes.
2019-01-02 14:05:54.378 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Creating new instance of command class COMMAND_CLASS_CLOCK
2019-01-02 14:05:54.379 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Command class COMMAND_CLASS_CLOCK, endpoint 0 created
2019-01-02 14:05:54.379 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 14: Application update is adding command class COMMAND_CLASS_CLOCK.
2019-01-02 14:05:54.379 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Adding command class COMMAND_CLASS_CLOCK to the list of supported command classes.
2019-01-02 14:05:54.379 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Creating new instance of command class COMMAND_CLASS_MANUFACTURER_SPECIFIC
2019-01-02 14:05:54.379 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Command class COMMAND_CLASS_MANUFACTURER_SPECIFIC, endpoint 0 created
2019-01-02 14:05:54.380 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 14: Application update is adding command class COMMAND_CLASS_MANUFACTURER_SPECIFIC.
2019-01-02 14:05:54.380 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Adding command class COMMAND_CLASS_MANUFACTURER_SPECIFIC to the list of supported command classes.
2019-01-02 14:05:54.380 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Creating new instance of command class COMMAND_CLASS_MULTI_CMD
2019-01-02 14:05:54.380 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Command class COMMAND_CLASS_MULTI_CMD, endpoint 0 created
2019-01-02 14:05:54.380 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 14: Application update is adding command class COMMAND_CLASS_MULTI_CMD.
2019-01-02 14:05:54.380 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Adding command class COMMAND_CLASS_MULTI_CMD to the list of supported command classes.
2019-01-02 14:05:54.381 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Creating new instance of command class COMMAND_CLASS_PROTECTION
2019-01-02 14:05:54.381 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Command class COMMAND_CLASS_PROTECTION, endpoint 0 created
2019-01-02 14:05:54.381 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 14: Application update is adding command class COMMAND_CLASS_PROTECTION.
2019-01-02 14:05:54.381 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Adding command class COMMAND_CLASS_PROTECTION to the list of supported command classes.
2019-01-02 14:05:54.381 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Creating new instance of command class COMMAND_CLASS_THERMOSTAT_SETPOINT
2019-01-02 14:05:54.382 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Command class COMMAND_CLASS_THERMOSTAT_SETPOINT, endpoint 0 created
2019-01-02 14:05:54.382 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 14: Application update is adding command class COMMAND_CLASS_THERMOSTAT_SETPOINT.
2019-01-02 14:05:54.382 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Adding command class COMMAND_CLASS_THERMOSTAT_SETPOINT to the list of supported command classes.
2019-01-02 14:05:54.382 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Creating new instance of command class COMMAND_CLASS_VERSION
2019-01-02 14:05:54.382 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Command class COMMAND_CLASS_VERSION, endpoint 0 created
2019-01-02 14:05:54.382 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 14: Application update is adding command class COMMAND_CLASS_VERSION.
2019-01-02 14:05:54.382 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Adding command class COMMAND_CLASS_VERSION to the list of supported command classes.
2019-01-02 14:05:54.382 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Creating new instance of command class COMMAND_CLASS_WAKE_UP
2019-01-02 14:05:54.383 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 14: Command class COMMAND_CLASS_WAKE_UP, endpoint 0 created
2019-01-02 14:05:54.383 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 14: Application update is adding command class COMMAND_CLASS_WAKE_UP.
2019-01-02 14:05:54.383 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Adding command class COMMAND_CLASS_WAKE_UP to the list of supported command classes.
2019-01-02 14:05:54.383 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 14: Application update - no transaction.
2019-01-02 14:05:54.383 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-02 14:05:54.383 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-02 14:05:54.634 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Is awake with 1 messages in the queue
2019-01-02 14:05:54.634 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: Start sleep timer at 5000ms
2019-01-02 14:05:54.635 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 14: Got an event from Z-Wave network: ZWaveNodeStatusEvent
2019-01-02 14:05:54.636 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 14: Node Status event - Node is AWAKE
2019-01-02 14:05:57.135 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:05:59.636 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:02.136 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:04.636 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:07.136 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:09.636 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:12.136 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:14.637 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:17.138 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:19.637 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:22.137 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:24.637 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:27.138 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:29.637 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:32.137 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:34.638 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:37.137 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:39.637 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:42.137 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:44.638 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:47.139 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:49.638 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:52.138 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:54.638 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:57.139 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:06:59.639 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:07:02.139 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:07:04.639 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:07:07.139 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:07:09.640 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:07:12.140 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:07:14.640 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:07:17.140 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:07:19.641 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF
2019-01-02 14:07:22.141 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: WakeupTimerTask 1 Messages waiting, state REQUEST_NIF

The device itself reports E5 (unable to connect to controller).

I could also see some changes of power consumptions being transmitted e.g. from rollershutters, so I’d assume things are generally working fine - It just seems as if the devices weren’t properly identified.

Would anybody have an idea on what could be the reason for this? As it’s gonna snow tomorrow and the heating still isn’t working in our livingroom, it would be great to get this sorted

In case I can provide any additional info, please let me know.
Many thanks in advance for your help!

[jeffryvu (Jeffry van de Vuurst)]

I have the exact same issue. I have a bunch of Fibaro zwave devices that are all recognized fine in OH1.8, but when I upgraded to 2.4 they all show up as unknown device.

[chris (Chris Jackson)]

First thing I would suggest to update to the latest snapshot binding as it fixes a bug with wakeup that I can see in your log.

@jeffryvu

I have a bunch of Fibaro zwave devices that are all recognized fine in OH1.8, but when I upgraded to 2.4 they all show up as unknown device.

Generally, there shouldn’t be any issues - what do you see in the debug logs? Any clue as to what the devices are?

[jeffryvu (Jeffry van de Vuurst)]

Most are Fibaro dimmers and some motion sensors.

The thing is, from the logs they look ok, see:
2019-01-02 15:34:26.189 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: Application Command Request (ALIVE:DONE)
2019-01-02 15:34:26.189 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: resetResendCount initComplete=true isDead=false
2019-01-02 15:34:26.189 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: Incoming command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0
2019-01-02 15:34:26.190 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 21: SECURITY not supported
2019-01-02 15:34:26.190 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 21: Received COMMAND_CLASS_SWITCH_MULTILEVEL V0 SWITCH_MULTILEVEL_REPORT
2019-01-02 15:34:26.190 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 21: Switch Multi Level report, value = 99
2019-01-02 15:34:26.190 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveCommandClassValueEvent
2019-01-02 15:34:26.191 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got an event from Z-Wave network: ZWaveCommandClassValueEvent
2019-01-02 15:34:26.191 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_SWITCH_MULTILEVEL, value = 99
2019-01-02 15:34:26.191 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: Commands processed 1.
2019-01-02 15:34:26.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 21: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@6ae47c29.
2019-01-02 15:34:26.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-01-02 15:34:26.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-01-02 15:34:26.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-02 15:34:26.192 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-02 15:34:26.193 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing

The issue is, from the Paper UI they all show as unknown device which means I cannot configure them and enable the channels. Or is there another way to configure?

[chris (Chris Jackson)]

@jeffryvu

The thing is, from the logs they look ok, see:

This is a very short log, and it’s clearly not ok and indicates that the device has not completed initialisation - which is consistent with it not knowing the device type.

[jeffryvu (Jeffry van de Vuurst)]

Sorry, should have mentioned that I tested one dimmer (node 21) and that I switched it on. I just copied the part of the log that shows that. It shows a COMMAND_CLASS_SWITCH_MULTILEVEL which is consistent with a dimmer and it shows the value going to 99. So I thought that looked ok.

Where do you see that initialisation has not completed?

I enabled tracing so the complete log is quite large. I restarted OH and copied the log since the restart:

2019-01-02 15:53:05.831 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.thing.binding.ThingHandlerFactory}={service.id=137, service.bundleid=240, service.scope=bundle, component.name=org.openhab.binding.zwave.internal.ZWaveHandlerFactory, component.id=29} - org.openhab.binding.zwave
2019-01-02 15:53:05.932 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTING - org.openhab.binding.zwave
2019-01-02 15:53:05.936 [DEBUG] [inding.zwave.internal.ZWaveActivator] - Z-Wave binding started. Version 2.5.0.201812281027
2019-01-02 15:53:05.936 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent STARTED - org.openhab.binding.zwave
2019-01-02 15:53:05.959 [DEBUG] [org.openhab.binding.zwave           ] - BundleEvent [unknown:512] - org.openhab.binding.zwave
2019-01-02 15:53:08.681 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Time zone set to 'Europe/Amsterdam'.
2019-01-02 15:53:08.709 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Locale set to 'en_NL'.
2019-01-02 15:53:08.713 [INFO ] [.core.internal.i18n.I18nProviderImpl] - Measurement system set to 'SIUnits'.
2019-01-02 15:53:09.086 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.core.events.EventFactory}={service.id=167, service.bundleid=240, service.scope=bundle, component.name=org.openhab.binding.zwave.event.BindingEventFactory, component.id=28} - org.openhab.binding.zwave
2019-01-02 15:53:10.248 [INFO ] [panel.internal.HABPanelDashboardTile] - Started HABPanel at /habpanel
2019-01-02 15:53:14.289 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.ConfigDescriptionProvider, org.eclipse.smarthome.config.core.ConfigOptionProvider}={service.id=219, service.bundleid=240, service.scope=bundle, component.name=org.openhab.binding.zwave.internal.ZWaveConfigProvider, component.id=26} - org.openhab.binding.zwave
2019-01-02 15:53:27.597 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.items'
2019-01-02 15:53:31.005 [INFO ] [thome.model.lsp.internal.ModelServer] - Started Language Server Protocol (LSP) service on port 5007
2019-01-02 15:53:31.745 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'default.sitemap'
2019-01-02 15:53:32.687 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Initializing ZWave serial controller.
2019-01-02 15:53:32.702 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initializing ZWave Controller zwave:serial_zstick:db85b9e2.
2019-01-02 15:53:32.702 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Scheduling network mesh heal for 11 hours time.
2019-01-02 15:53:32.702 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Connecting to serial port 'COM4'
2019-01-02 15:53:32.788 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=315, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:32.792 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=319, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:32.788 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=316, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:32.788 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=317, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:32.788 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=318, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:32.823 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node6.
2019-01-02 15:53:32.823 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node26.
2019-01-02 15:53:32.882 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node27.
2019-01-02 15:53:32.886 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 6: MANUFACTURER not set
2019-01-02 15:53:32.886 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node4.
2019-01-02 15:53:32.886 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node28.
2019-01-02 15:53:32.894 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 26: MANUFACTURER not set
2019-01-02 15:53:32.894 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=320, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:32.894 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=321, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:32.925 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 4: MANUFACTURER not set
2019-01-02 15:53:32.925 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 28: MANUFACTURER not set
2019-01-02 15:53:32.925 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=322, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:32.925 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=323, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:32.941 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 27: MANUFACTURER not set
2019-01-02 15:53:32.941 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node25.
2019-01-02 15:53:32.941 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=324, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:32.957 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node5.
2019-01-02 15:53:32.957 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node8.
2019-01-02 15:53:32.957 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 25: MANUFACTURER not set
2019-01-02 15:53:32.957 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node24.
2019-01-02 15:53:32.957 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 24: MANUFACTURER not set
2019-01-02 15:53:32.957 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 8: MANUFACTURER not set
2019-01-02 15:53:32.957 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=325, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:32.957 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=326, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:32.957 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node13.
2019-01-02 15:53:32.976 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 13: MANUFACTURER not set
2019-01-02 15:53:32.957 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: MANUFACTURER not set
2019-01-02 15:53:32.980 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=328, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:32.972 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=327, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:32.972 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node23.
2019-01-02 15:53:33.032 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=329, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:33.047 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node7.
2019-01-02 15:53:33.067 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 7: MANUFACTURER not set
2019-01-02 15:53:33.067 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node22.
2019-01-02 15:53:33.075 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=330, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:33.079 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node12.
2019-01-02 15:53:33.095 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 22: MANUFACTURER not set
2019-01-02 15:53:33.095 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 23: MANUFACTURER not set
2019-01-02 15:53:33.142 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: MANUFACTURER not set
2019-01-02 15:53:33.157 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node11.
2019-01-02 15:53:33.157 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=331, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:33.157 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=332, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:33.173 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node9.
2019-01-02 15:53:33.173 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 9: MANUFACTURER not set
2019-01-02 15:53:33.173 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node31.
2019-01-02 15:53:33.188 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 11: MANUFACTURER not set
2019-01-02 15:53:33.188 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:db85b9e2:node21.
2019-01-02 15:53:33.211 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 21: MANUFACTURER not set
2019-01-02 15:53:33.221 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 31: MANUFACTURER not set
2019-01-02 15:53:33.973 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Starting receive thread
2019-01-02 15:53:33.973 [INFO ] [ing.zwave.handler.ZWaveSerialHandler] - Serial port is initialized
2019-01-02 15:53:33.973 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Starting ZWave thread: Receive
2019-01-02 15:53:33.973 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Initialising ZWave controller
2019-01-02 15:53:33.973 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 21
2019-01-02 15:53:34.005 [INFO ] [ve.internal.protocol.ZWaveController] - Starting ZWave controller
2019-01-02 15:53:34.005 [INFO ] [ve.internal.protocol.ZWaveController] - ZWave timeout is set to 5000ms. Soft reset is false.
2019-01-02 15:53:34.005 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2019-01-02 15:53:34.017 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Creating ZWave discovery service for zwave:serial_zstick:db85b9e2 with scan time of 30
2019-01-02 15:53:34.019 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Active zwave:serial_zstick:db85b9e2
2019-01-02 15:53:34.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-02 15:53:34.019 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-02 15:53:34.019 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.discovery.DiscoveryService}={service.id=333, service.bundleid=240, service.scope=singleton} - org.openhab.binding.zwave
2019-01-02 15:53:34.019 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2019-01-02 15:53:35.465 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.68.109:8080
2019-01-02 15:53:35.634 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.68.109:8443
2019-01-02 15:53:36.720 [INFO ] [arthome.ui.paper.internal.PaperUIApp] - Started Paper UI at /paperui
2019-01-02 15:53:36.810 [INFO ] [ui.habmin.internal.servlet.HABminApp] - Started HABmin servlet at /habmin
2019-01-02 15:53:37.069 [DEBUG] [.ZWaveController$InitializeDelayTask] - Initialising network
2019-01-02 15:53:37.171 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2019-01-02 15:53:37.171 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 0 to queue - size 1
2019-01-02 15:53:37.171 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-02 15:53:37.171 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2019-01-02 15:53:37.171 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = GetVersion (0x15), type = Request
2019-01-02 15:53:37.171 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -23
2019-01-02 15:53:37.171 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 15 E9 
2019-01-02 15:53:37.171 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2019-01-02 15:53:37.187 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-01-02 15:53:37.187 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 0: Transaction Start type GetVersion 
2019-01-02 15:53:37.187 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-02 15:53:37.187 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2019-01-02 15:53:37.187 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2019-01-02 15:53:37.187 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2019-01-02 15:53:37.187 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Jan 02 15:53:39 CET 2019 - 2000ms
2019-01-02 15:53:37.187 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-02 15:53:37.187 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2019-01-02 15:53:37.202 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Jan 02 15:53:39 CET 2019 - 1985ms
2019-01-02 15:53:37.202 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2019-01-02 15:53:37.202 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 1 to queue - size 1
2019-01-02 15:53:37.202 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-02 15:53:37.202 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2019-01-02 15:53:37.202 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2019-01-02 15:53:37.202 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Jan 02 15:53:39 CET 2019 - 1985ms
2019-01-02 15:53:37.202 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2019-01-02 15:53:37.202 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 2 to queue - size 2
2019-01-02 15:53:37.202 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-02 15:53:37.202 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2019-01-02 15:53:37.202 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2019-01-02 15:53:37.202 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Jan 02 15:53:39 CET 2019 - 1985ms
2019-01-02 15:53:37.202 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-01-02 15:53:37.202 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 
2019-01-02 15:53:37.202 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-02 15:53:37.202 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2019-01-02 15:53:37.202 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 32 2E 37 38 00 01 9B 
2019-01-02 15:53:37.202 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 10 01 15 5A 2D 57 61 76 65 20 32 2E 37 38 00 01 9B 
2019-01-02 15:53:37.202 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -101
2019-01-02 15:53:37.202 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2019-01-02 15:53:37.218 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 5A 2D 57 61 76 65 20 32 2E 37 38 00 01 
2019-01-02 15:53:37.218 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2019-01-02 15:53:37.218 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2019-01-02 15:53:37.218 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 3 to queue - size 3
2019-01-02 15:53:37.218 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-02 15:53:37.218 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2019-01-02 15:53:37.218 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2019-01-02 15:53:37.218 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Jan 02 15:53:39 CET 2019 - 1969ms
2019-01-02 15:53:37.218 [DEBUG] [rialmessage.GetSucNodeIdMessageClass] - Get SUC NodeID
2019-01-02 15:53:37.218 [TRACE] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2019-01-02 15:53:37.218 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 4 to queue - size 4
2019-01-02 15:53:37.218 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-02 15:53:37.218 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2019-01-02 15:53:37.218 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2019-01-02 15:53:37.218 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Jan 02 15:53:39 CET 2019 - 1969ms
2019-01-02 15:53:37.233 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-02 15:53:37.233 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-02 15:53:37.233 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-01-02 15:53:37.233 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-02 15:53:37.233 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-02 15:53:37.233 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2019-01-02 15:53:37.233 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2019-01-02 15:53:37.233 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Jan 02 15:53:39 CET 2019 - 1954ms
2019-01-02 15:53:37.280 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2019-01-02 15:53:37.280 [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 32 2E 37 38 00 01 
2019-01-02 15:53:37.280 [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 32 2E 37 38 00 01 
2019-01-02 15:53:37.280 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-02 15:53:37.280 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-01-02 15:53:37.280 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 0: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-02 15:53:37.280 [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 32 2E 37 38 00 01 
2019-01-02 15:53:37.280 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
2019-01-02 15:53:37.357 [DEBUG] [serialmessage.GetVersionMessageClass] - Got MessageGetVersion response. Version=Z-Wave 2.78, Library Type=1
2019-01-02 15:53:37.357 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 0: Transaction COMPLETED
2019-01-02 15:53:37.357 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 0: TransactionAdvance ST: DONE
2019-01-02 15:53:37.361 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 0: TransactionAdvance WT: null {}
2019-01-02 15:53:37.365 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 0: TransactionAdvance RX: Message: class=GetVersion[21], type=Response[1], dest=255, callback=0, payload=5A 2D 57 61 76 65 20 32 2E 37 38 00 01 
2019-01-02 15:53:37.365 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 0: TransactionAdvance TO: DONE
2019-01-02 15:53:37.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 178ms
2019-01-02 15:53:37.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 0: Transaction completed
2019-01-02 15:53:37.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:0 DONE
2019-01-02 15:53:37.369 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2019-01-02 15:53:37.374 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-02 15:53:37.374 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-02 15:53:37.405 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2019-01-02 15:53:37.405 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = MemoryGetId (0x20), type = Request
2019-01-02 15:53:37.405 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -36
2019-01-02 15:53:37.405 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 20 DC 
2019-01-02 15:53:37.405 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2019-01-02 15:53:37.405 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-01-02 15:53:37.405 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 1: Transaction Start type MemoryGetId 
2019-01-02 15:53:37.405 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-02 15:53:37.405 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2019-01-02 15:53:37.405 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2019-01-02 15:53:37.405 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2019-01-02 15:53:37.405 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2019-01-02 15:53:37.405 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Jan 02 15:53:39 CET 2019 - 2000ms
2019-01-02 15:53:37.405 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-02 15:53:37.405 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2019-01-02 15:53:37.405 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Jan 02 15:53:39 CET 2019 - 2000ms
2019-01-02 15:53:37.405 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-01-02 15:53:37.405 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 
2019-01-02 15:53:37.405 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-02 15:53:37.405 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2019-01-02 15:53:37.405 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 08 01 20 01 84 E4 E9 01 5F 
2019-01-02 15:53:37.405 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 08 01 20 01 84 E4 E9 01 5F 
2019-01-02 15:53:37.405 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 95
2019-01-02 15:53:37.405 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2019-01-02 15:53:37.421 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01 84 E4 E9 01 
2019-01-02 15:53:37.421 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2019-01-02 15:53:37.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-02 15:53:37.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-02 15:53:37.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-01-02 15:53:37.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-02 15:53:37.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-02 15:53:37.421 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2019-01-02 15:53:37.421 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2019-01-02 15:53:37.421 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Jan 02 15:53:39 CET 2019 - 1984ms
2019-01-02 15:53:37.421 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2019-01-02 15:53:37.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=01 84 E4 E9 01 
2019-01-02 15:53:37.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=01 84 E4 E9 01 
2019-01-02 15:53:37.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-02 15:53:37.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-01-02 15:53:37.421 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 1: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-02 15:53:37.421 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=01 84 E4 E9 01 
2019-01-02 15:53:37.431 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
2019-01-02 15:53:37.431 [DEBUG] [erialmessage.MemoryGetIdMessageClass] - Got MessageMemoryGetId response. Home id = 0x184e4e9, Controller Node id = 1
2019-01-02 15:53:37.431 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1: Transaction COMPLETED
2019-01-02 15:53:37.431 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 1: TransactionAdvance ST: DONE
2019-01-02 15:53:37.431 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 1: TransactionAdvance WT: null {}
2019-01-02 15:53:37.431 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 1: TransactionAdvance RX: Message: class=MemoryGetId[32], type=Response[1], dest=255, callback=0, payload=01 84 E4 E9 01 
2019-01-02 15:53:37.431 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 1: TransactionAdvance TO: DONE
2019-01-02 15:53:37.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 26ms
2019-01-02 15:53:37.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 1: Transaction completed
2019-01-02 15:53:37.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:1 DONE
2019-01-02 15:53:37.435 [TRACE] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2019-01-02 15:53:37.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-02 15:53:37.435 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-02 15:53:37.435 [TRACE] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2019-01-02 15:53:37.435 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = SerialApiGetCapabilities (0x7), type = Request
2019-01-02 15:53:37.435 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -5
2019-01-02 15:53:37.435 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 03 00 07 FB 
2019-01-02 15:53:37.439 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2019-01-02 15:53:37.443 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-01-02 15:53:37.443 [TRACE] [e.internal.protocol.ZWaveTransaction] - TID 2: Transaction Start type SerialApiGetCapabilities 
2019-01-02 15:53:37.443 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-02 15:53:37.443 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2019-01-02 15:53:37.443 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2019-01-02 15:53:37.443 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2019-01-02 15:53:37.447 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2019-01-02 15:53:37.447 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Jan 02 15:53:39 CET 2019 - 2000ms
2019-01-02 15:53:37.447 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-02 15:53:37.447 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2019-01-02 15:53:37.447 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Jan 02 15:53:39 CET 2019 - 2000ms
2019-01-02 15:53:37.447 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-01-02 15:53:37.447 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 
2019-01-02 15:53:37.447 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-02 15:53:37.451 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2019-01-02 15:53:37.455 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 2B 01 07 03 07 00 86 00 02 00 01 FE 80 FE 88 0F 00 00 00 FB 97 7F 82 07 00 00 80 00 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 C2 
2019-01-02 15:53:37.455 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 2B 01 07 03 07 00 86 00 02 00 01 FE 80 FE 88 0F 00 00 00 FB 97 7F 82 07 00 00 80 00 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 C2 
2019-01-02 15:53:37.455 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -62
2019-01-02 15:53:37.455 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2019-01-02 15:53:37.455 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 03 07 00 86 00 02 00 01 FE 80 FE 88 0F 00 00 00 FB 97 7F 82 07 00 00 80 00 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2019-01-02 15:53:37.455 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2019-01-02 15:53:37.459 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-02 15:53:37.459 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-02 15:53:37.459 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-01-02 15:53:37.459 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-02 15:53:37.467 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-02 15:53:37.467 [TRACE] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2019-01-02 15:53:37.467 [TRACE] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2019-01-02 15:53:37.467 [TRACE] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Jan 02 15:53:39 CET 2019 - 1980ms
2019-01-02 15:53:37.467 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2019-01-02 15:53:37.467 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=03 07 00 86 00 02 00 01 FE 80 FE 88 0F 00 00 00 FB 97 7F 82 07 00 00 80 00 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2019-01-02 15:53:37.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=03 07 00 86 00 02 00 01 FE 80 FE 88 0F 00 00 00 FB 97 7F 82 07 00 00 80 00 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2019-01-02 15:53:37.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-02 15:53:37.555 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-01-02 15:53:37.559 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 2: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0
2019-01-02 15:53:37.559 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SerialApiGetCapabilities[7], type=Response[1], dest=255, callback=0, payload=03 07 00 86 00 02 00 01 FE 80 FE 88 0F 00 00 00 FB 97 7F 82 07 00 00 80 00 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 
2019-01-02 15:53:37.559 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
2019-01-02 15:53:37.559 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Handle Message Serial API Get Capabilities - Length 40
2019-01-02 15:53:37.559 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - API Version    = 3.7
2019-01-02 15:53:37.563 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Manufacture ID = 0x86
2019-01-02 15:53:37.563 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Device Type    = 0x2
2019-01-02 15:53:37.563 [DEBUG] [SerialApiGetCapabilitiesMessageClass] - Device ID      = 0x1
2019-01-02 15:53:37.563 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: SerialApiGetInitData
2019-01-02 15:53:37.563 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: SerialApiApplicationNodeInfo
2019-01-02 15:53:37.563 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: ApplicationCommandHandler
2019-01-02 15:53:37.563 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: GetControllerCapabilities
2019-01-02 15:53:37.563 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: SerialApiSetTimeouts
2019-01-02 15:53:37.563 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: SerialApiGetCapabilities
2019-01-02 15:53:37.563 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: SerialApiSoftReset
2019-01-02 15:53:37.563 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: RfReceiveMode
2019-01-02 15:53:37.563 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: SendNodeInfo
2019-01-02 15:53:37.563 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: SendData
2019-01-02 15:53:37.563 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: SendDataMulti
2019-01-02 15:53:37.563 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: GetVersion
2019-01-02 15:53:37.563 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: SendDataAbort
2019-01-02 15:53:37.563 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: RfPowerLevelSet
2019-01-02 15:53:37.563 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: SendDataMeta
2019-01-02 15:53:37.563 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: GetRandom
2019-01-02 15:53:37.567 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: MemoryGetId
2019-01-02 15:53:37.567 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: MemoryGetByte
2019-01-02 15:53:37.567 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: MemoryPutByte
2019-01-02 15:53:37.567 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: ReadMemory
2019-01-02 15:53:37.567 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: WriteMemory
2019-01-02 15:53:37.567 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: IdentifyNode
2019-01-02 15:53:37.567 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: SetDefault
2019-01-02 15:53:37.567 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: ReplicationCommandComplete
2019-01-02 15:53:37.567 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: ReplicationSendData
2019-01-02 15:53:37.575 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: AssignReturnRoute
2019-01-02 15:53:37.587 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: DeleteReturnRoute
2019-01-02 15:53:37.587 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: RequestNodeNeighborUpdate
2019-01-02 15:53:37.591 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: ApplicationUpdate
2019-01-02 15:53:37.591 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: AddNodeToNetwork
2019-01-02 15:53:37.591 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: RemoveNodeFromNetwork
2019-01-02 15:53:37.591 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: ControllerChange
2019-01-02 15:53:37.591 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: SetLearnMode
2019-01-02 15:53:37.591 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: AssignSucReturnRoute
2019-01-02 15:53:37.591 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: EnableSuc
2019-01-02 15:53:37.591 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: RequestNetworkUpdate
2019-01-02 15:53:37.591 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: SetSucNodeID
2019-01-02 15:53:37.591 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: DeleteSUCReturnRoute
2019-01-02 15:53:37.591 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: GetSucNodeId
2019-01-02 15:53:37.591 [TRACE] [SerialApiGetCapabilitiesMessageClass] - Supports: SendSucId

[chris (Chris Jackson)]

@jeffryvu

Where do you see that initialisation has not completed?

It can be inferred from the following

@jeffryvu

2019-01-02 15:34:26.190 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 21: Received COMMAND_CLASS_SWITCH_MULTILEVEL V0 SWITCH_MULTILEVEL_REPORT

This shows the command class is version 0, which should not be correct if the initialisation had completed.

Unfortunately the log is way too short to be of any use - the binding itself has still not really initialised, let alone any of the devices. I would need to see potentially at least a few minutes of logging to see what’s happening - can you provide a longer log and I will take a look.

@jeffryvu

I enabled tracing so the complete log is quite large.

Please just use DEBUG - it should be enough. TRACE is very low level and will make the log a lot larger and harder to read.

Also, please use code fences when posting logs - I’ve edited your log to make it easier to read.

[phate (David Schulz)]

Hey @chris,

many thanks for your quick reaction! As always, I’m surprised about how quickly you manage to respond to support requests - Chapeau!

I’d love to try out the new snapshot version and then get you a complete log. Could you please also drop a hint on where to download the latest snapshot? I’ve tried here https://openhab.ci.cloudbees.com/job/openHAB2-Bundles/lastBuild/org.openhab.binding%24org.openhab.binding.zwave/, but was confronted with a " This DEV@cloud account is currently unavailable" message. Also checked here https://github.com/openhab/org.openhab.binding.zwave/tree/master, but couldn’t locate no .jar file in the repo.
Many thanks for your help again!

–
Edit: Here’s already a larger debug log of today using binding 2.4.0: zwave_log.txt (1003.2 KB)

[phate (David Schulz)]

In addition, I can confirm from Paper UI the command classes apparently having been properly determined while zwave version remains on 0.0:

This situation is present for all my devices - Wired as well as battery powered.

[sihui]

@phate

where to download the latest snapshot?

https://ci.openhab.org/job/openHAB2-Bundles/modules

[phate (David Schulz)]

many thanks, @sihui!
I put the .jar into the addons folder and restarted the OH2 service. Checking the log shows this error twice:

2019-01-02 22:36:01.446 [WARN ] [org.apache.felix.fileinstall        ] - Error while starting bundle: file:/usr/share/openhab2/addons/org.openhab.binding.zwave-2.5.0-SNAPSHOT.jar
org.osgi.framework.BundleException: Could not resolve module: org.openhab.binding.zwave [287]
  Unresolved requirement: Import-Package: gnu.io

	at org.eclipse.osgi.container.Module.start(Module.java:444) ~[?:?]
	at org.eclipse.osgi.internal.framework.EquinoxBundle.start(EquinoxBundle.java:383) ~[?:?]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundle(DirectoryWatcher.java:1260) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startBundles(DirectoryWatcher.java:1233) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.startAllBundles(DirectoryWatcher.java:1221) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.doProcess(DirectoryWatcher.java:515) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.process(DirectoryWatcher.java:365) [10:org.apache.felix.fileinstall:3.6.4]
	at org.apache.felix.fileinstall.internal.DirectoryWatcher.run(DirectoryWatcher.java:316) [10:org.apache.felix.fileinstall:3.6.4]

Karaf reports the Snapshot being in use:

Any suggestions?

[5iver (Scott Rushworth)]

@phate

Karaf reports the Snapshot being in use

Installed, but not Active. Since you’ve manually installed, you’ll need to manually resolve the dependencies… in this case:

feature:install openhab-transport-serial

Replace bundle with custom version for real world testing

First, uninstall the production version. If it was manually added to addons.cfg, it will need to be removed from there. If not, uninstall through a UI or Karaf. Then copy the jar file into the /addons/ directory. The location of addons depends on the OH installation method, and can be found in the documentation. Once copied into addons, it is best to keep the file name consistent when upgrading, or the older version may get cached, requiring the older bundle to be uninstalled through Karaf, or …

Zigbee and zwave manual install script

A number of people have run into trouble performing manual installs of the Zigbee and Z-Wave bindings. A manual install (dropping the jar into addons) is rarely needed, but some people prefer a manual install over apt-get, or want to use a stable OH release with a recent Zigbee or Z-Wave binding. Here is a script that will hopefully make it easier to install, upgrade, and uninstall these bindings, and prevent some of the common issues. Who would benefit from this script: Anyone wanting to tes…

[phate (David Schulz)]

That worked out fine, many thanks!
To me, the binding now appears to be working properly (see also within this log that shows the success immediately after having resolved the dependency as described by @5iver: zwave_log_250_initialstart.txt (347.1 KB)

All things remained unknown though. Thus, I’ve removed my thermostat thing again and re-added it via the inbox in Paper UI. See here for the log results covering some minutes of traffic: zwave_log_250_node14.txt (1006.6 KB)

Still, I cannot see any thing being properly identified. Maybe, someone can find a hint within the logs?
Thanks again!

[jeffryvu (Jeffry van de Vuurst)]

Thanks for your swift replies Chris, much appreciated!

I’ve set logging to debug and restarted OH. I’m attaching a few zwave xml files, the openhab.log and events.log.

events.log (17.5 KB)
openhab.log (530.0 KB)
network_0184e4e9__node_5.xml (2.3 KB)
network_0184e4e9__node_6.xml (1.9 KB)
network_0184e4e9__node_7.xml (2.3 KB)

[chris (Chris Jackson)]

There are 2 issues I note in the log. The main problem is that the controller seems to be rejecting most or all commands being sent to the controller from the binding. From below, we see the binding send a command, which is ACK’d by the controller as being received OK, and then rejected for some reason.

What controller do you have?

The other thing I note is that some of your devices seem to flood the network. Possibly this is misconfiguration of the associations in the device (but I think it’s unlikely given the large number of frames), or it might be indicative of some other problem (maybe related to the above issue) if the controller is not receiving the data. In the event that the controller doesn’t ACK messages sent from devices, then the device will resend, and you can end up with multiple messages being received.

Above we see around 20 messages being received - the information is exactly the same in all of them, although about 2/3rds of the way through something in the control area does change and I need to have a better look at that to see what it means.

This same thing happens whenever data is received from lots of nodes, so my guess is some sort of controller problem. This isn’t something the binding can really influence, so I’m suspicious that there is something wrong with the controller. Have you reset it?

[chris (Chris Jackson)]

@jeffryvu

I’ve set logging to debug and restarted OH. I’m attaching a few zwave xml files, the openhab.log and events.log.

In the log here there is no data received from any device so I’m not sure what I can comment on here. There’s nothing especially wrong that I can see, but there aren’t any device responses at all.

The XML files are also basically empty, so also indicate no communication with the devices.

I’m not sure what to suggest - first would be a soft reset of the controller (ie remove it from the USB so that it power cycles).

[phate (David Schulz)]

Hi @chris,

many thanks for your effort here! Highly appreciated!
I’m using an Aeotec Gen5 stick (see https://aeotec.com/z-wave-usb-stick).So far, I’ve not yet reset it as I’m not too eager about having to re-include all nodes into the network.
With OH 1.8, I’ve used Habmin in order to include the nodes and I’ve ensured each node also has the controller in their groups.
From what I see in Paper UI, the nodes don’t appear to have any neighbours assigned currently:

With OH 2, everything also worked out fine so far (I’m using OH 2 for a couple of months now). It’s just been the latest update onto 2.4 that resulted in this situation, not the major upgrade from OH 1 to OH 2.
As far as I understood, the way the zwave stick is identified / configured has also changed within this latest update, hasn’t it? I’ve so far not adjusted any of the settings that you can apply to the stick via Paper UI (desite the serial port used). Maybe, there’s something that could be tried out in that regards? Or is a complete reset and building up the network again from scratch the only possible option right now?

Many thanks again and best regards!

[chris (Chris Jackson)]

@phate

So far, I’ve not yet reset it as I’m not too eager about having to re-include all nodes into the network.

I didn’t mean a hard reset - just a soft reset for starters.

@phate

From what I see in Paper UI, the nodes don’t appear to have any neighbours assigned currently:

Yes, but at the moment there is no communication with the device, so you can’t rely on any of this information until you resolve the underlying issue.

@phate

As far as I understood, the way the zwave stick is identified / configured has also changed within this latest update, hasn’t it?

Not that I’m aware of, no. There is the option to configure using text files now, but the binding really doesn’t see any difference (it knows nothing about UIs or text files). I think that the way the dongle communicates is largely the same in 2.3 and 2.4. Higher level handling of transactions (ie how messages sent and received are correlated) has changed.

@phate

I’ve so far not adjusted any of the settings that you can apply to the stick

I don’t think there are very many (or any?) that can influence this.

@phate

Or is a complete reset and building up the network again from scratch the only possible option right now?

As above, the first thing I would do is to do a soft reset - ie remove the stick from the USB, wait a bit, then put it back.

[jeffryvu (Jeffry van de Vuurst)]

Thanks, it was a matter of soft resetting the controller. Duh!

[phate (David Schulz)]

Many thanks, this also solved it for me! I could meanwhile get all my rollershutters running again and also the thermostat is working properly. After a while, the door sensor joined in as well. I’m only still missing the smoke detectors and trying to wake them up manually didn’t yet lead to any success, so I hope to be seeing them soon.

What puzzles me a bit is that for one of my wall plug switches (an AEON Labs ZW075) is constantly writing this message package into the log:

2019-01-03 19:41:30.282 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 14 00 04 00 02 0E 32 02 21 74 00 00 00 00 00 00 00 00 00 00 86 
2019-01-03 19:41:30.283 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0E 32 02 21 74 00 00 00 00 00 00 00 00 00 00 
2019-01-03 19:41:30.284 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=2, callback=0, payload=00 02 0E 32 02 21 74 00 00 00 00 00 00 00 00 00 00 
2019-01-03 19:41:30.284 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-01-03 19:41:30.284 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Application Command Request (ALIVE:DONE)
2019-01-03 19:41:30.284 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: resetResendCount initComplete=true isDead=false
2019-01-03 19:41:30.285 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: Incoming command class COMMAND_CLASS_METER, endpoint 0
2019-01-03 19:41:30.285 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: SECURITY NOT required on COMMAND_CLASS_METER
2019-01-03 19:41:30.285 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 2: Received COMMAND_CLASS_METER V3 METER_REPORT
2019-01-03 19:41:30.285 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 2: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
2019-01-03 19:41:30.286 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got an event from Z-Wave network: ZWaveMeterValueEvent
2019-01-03 19:41:30.286 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_METER, value = 0E+1
2019-01-03 19:41:30.286 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Updating channel state zwave:device:30ef5acb:node2:meter_watts to 0 [DecimalType]
2019-01-03 19:41:30.287 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Commands processed 1.
2019-01-03 19:41:30.287 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@77ac7e0e.
2019-01-03 19:41:30.287 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-01-03 19:41:30.287 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-01-03 19:41:30.288 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-03 19:41:30.288 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

I have an equal one at another place as well that doesn’t flood so much into my logs. Both of them are switched on with a consumer being switched off, so I don’t quite understand why only this plug is constantly publishing 0 watts to the controller… Everything works fine in that regards though, it’s just the flooding of the logs (and maybe also the network itself, which makes me afraid of further issues coming up in the future). Maybe, someone has an idea of where to configure this? I’ve checked the properties in Paper UI, but they’re the same for both plugs.

Other than that, it turns out that the hexadecimal part of the identifier (e.g. zwave:device:a22ef60c:node7:sensor_door) has changed for all my devices somewhere on the way, so I’ll have to adjust my items accordingly.

Many many thanks once again, @chris for your splendid help on this one!