Fibaro Switch 2 FGS223 Not recognized

zwave
Tags: #<Tag:0x00007f014ac6ba68>

(Joan Pujol) #1

Hi,

I tried to bind my first zwave device (a Fibaro switch FGS223) and I successfully added it but it isn’t recognized.
I’ve checked that it’s in the database.

I’ve put the device at few centimeters of the controller (an AEON Gen5 stick).
Also I tried to make a heal on the switch device.

This are relevant logs. From inclusion:

2019-01-12 10:40:28.415 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do

2019-01-12 10:40:28.420 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:e74f9ee6

2019-01-12 10:40:28.424 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 0

2019-01-12 10:40:28.429 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.

2019-01-12 10:40:28.432 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion

2019-01-12 10:40:28.441 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 69 to queue - size 1

2019-01-12 10:40:28.445 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-12 10:40:28.460 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 01 2C 9D

2019-01-12 10:40:28.464 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-01-12 10:40:28.465 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2019-01-12 10:40:28.467 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-01-12 10:40:28.466 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 69: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 44

2019-01-12 10:40:28.469 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-01-12 10:40:28.471 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 69: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 44

2019-01-12 10:40:28.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2019-01-12 10:40:28.476 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 2C 01 00 00 9F

2019-01-12 10:40:28.478 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-12 10:40:28.480 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-01-12 10:40:28.481 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=44, payload=2C 01 00 00

2019-01-12 10:40:28.504 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=44, payload=2C 01 00 00

2019-01-12 10:40:28.507 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 69: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 44

2019-01-12 10:40:28.509 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-01-12 10:40:28.510 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 69: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 44

2019-01-12 10:40:28.511 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 69: (Callback 44)

2019-01-12 10:40:28.517 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2019-01-12 10:40:28.518 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 69: callback 44

2019-01-12 10:40:28.521 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=44, payload=2C 01 00 00

2019-01-12 10:40:28.525 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart

2019-01-12 10:40:28.526 [arthome.event.BindingEvent] - org.openhab.binding.zwave.event.BindingEvent@1bed3a0

2019-01-12 10:40:28.527 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 69: Transaction COMPLETED

2019-01-12 10:40:28.529 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 63ms

2019-01-12 10:40:28.531 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 69: Transaction completed

2019-01-12 10:40:28.533 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:69 DONE

2019-01-12 10:40:28.535 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-12 10:40:28.537 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-12 10:40:30.471 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery completed

2019-01-12 10:40:30.512 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery could not resolve to a thingType! Manufacturer data not known.

2019-01-12 10:40:30.519 [home.event.InboxAddedEvent] - Discovery Result with UID ‘zwave:device:e74f9ee6:node3’ has been added.

2019-01-12 10:40:30.518 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing ‘zwave:device:e74f9ee6:node3’ to inbox.

and from the healing:

2019-01-12 10:42:34.535 [hingStatusInfoChangedEvent] - 'zwave:device:e74f9ee6:node3' changed from UNINITIALIZED to INITIALIZING

2019-01-12 10:42:34.536 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:e74f9ee6:node3.

2019-01-12 10:42:34.545 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: MANUFACTURER not set

2019-01-12 10:42:34.546 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller status changed to ONLINE.

2019-01-12 10:42:34.548 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller is ONLINE. Starting device initialisation.

2019-01-12 10:42:34.552 [hingStatusInfoChangedEvent] - 'zwave:device:e74f9ee6:node3' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE): Controller is offline

2019-01-12 10:42:34.557 [hingStatusInfoChangedEvent] - 'zwave:device:e74f9ee6:node3' changed from OFFLINE (BRIDGE_OFFLINE): Controller is offline to ONLINE

2019-01-12 10:42:34.562 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties.

2019-01-12 10:42:34.563 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:e74f9ee6:node3' has been updated.

2019-01-12 10:42:34.564 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties. MAN=2147483647

2019-01-12 10:42:34.565 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Properties synchronised

2019-01-12 10:42:34.577 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.

2019-01-12 10:42:34.579 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising Thing Node...

2019-01-12 10:42:34.580 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:e74f9ee6:node3' has been updated.

2019-01-12 10:42:34.581 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling intialised at 1800 seconds - start in 579600 milliseconds.

2019-01-12 10:42:34.583 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Device initialisation complete.

2019-01-12 10:45:37.315 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update received

2019-01-12 10:45:37.326 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update set action_heal to true (Boolean)

2019-01-12 10:45:37.332 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Starting heal on node!

2019-01-12 10:45:37.337 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Can not start heal as initialisation is not complete (SECURITY_REPORT).

2019-01-12 10:45:37.344 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update set binding_cmdrepollperiod to 1500 (BigDecimal)

2019-01-12 10:45:37.349 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update set action_failed to false (Boolean)

2019-01-12 10:45:37.356 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update set action_remove to false (Boolean)

2019-01-12 10:45:37.361 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update set binding_pollperiod to 86400 (BigDecimal)

2019-01-12 10:45:37.367 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling intialised at 86400 seconds - start in 5529600 milliseconds.

2019-01-12 10:45:37.371 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored node_id to 3 (BigDecimal)

2019-01-12 10:45:37.382 [me.event.ThingUpdatedEvent] - Thing 'zwave:device:e74f9ee6:node3' has been updated.

2019-01-12 10:53:55.681 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave inclusion controller finalised

2019-01-12 10:53:55.686 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave inclusion controller finalised

The last part that says initializing and Manufacturing set means that device cant take hours to initiaize?


(Chris Jackson) #2

Unfortunately this isn’t the relevant parts of the logs… We need to see the manufacturer information from the device - so either the relevant part of the initialisation, or, this information should be in the device properties.

You also don’t say what version of the binding you are using?

Also, when posting logs, please use code fences - not quotes as it’s very difficult to read and use.


(Joan Pujol) #3

Thanks Chris. I will provide all the requested information. About the manufacturer device how can I get it? It’s logged when the device is included first time?

Cheers,


(Chris Jackson) #4

It is logged, but it is also shown in the device properties in PaperUI or HABmin.


(Joan Pujol) #5

Hi Chris,

I’m using binding-zwave - 2.4.0 and OpenHab 2.4.
I looked at log and at thing config from PaperUI but I don’t see anything close to device properties:

I tried to remove and add the device several times tand also tried several times to press three times the ¡b¡ service button to wake up the device and send a Z-Wave command frame.
I attach at the end more than 1 hour of log from a remove+inclusion.

What it seems to happen is that device isn’t correctly initialized. But what I can do for it to initialize?

Log

2019-01-12 20:17:34.355 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Handler disposed. Unregistering listener.
2019-01-12 20:17:34.467 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 3: Serialise aborted as static stages not complete
2019-01-12 20:17:34.481 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent UNREGISTERING - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=426, service.bundleid=224, service.scope=singleton} - org.openhab.binding.zwave
2019-01-12 20:17:38.814 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:e74f9ee6
2019-01-12 20:17:38.817 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave inclusion process not running - nothing to do
2019-01-12 20:17:38.821 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Start zwave:serial_zstick:e74f9ee6
2019-01-12 20:17:38.824 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 1
2019-01-12 20:17:38.834 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2019-01-12 20:17:38.837 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller start inclusion
2019-01-12 20:17:38.841 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:false.
2019-01-12 20:17:38.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 17 to queue - size 1
2019-01-12 20:17:38.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-12 20:17:38.853 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 81 08 39 
2019-01-12 20:17:38.857 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 81 08 39 
2019-01-12 20:17:38.861 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-01-12 20:17:38.863 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-01-12 20:17:38.865 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-12 20:17:38.865 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 17: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 8
2019-01-12 20:17:38.868 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-12 20:17:38.870 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 08 01 00 00 BB 
2019-01-12 20:17:38.873 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 17: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 8
2019-01-12 20:17:38.874 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=8, payload=08 01 00 00 
2019-01-12 20:17:38.877 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-01-12 20:17:38.880 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=8, payload=08 01 00 00 
2019-01-12 20:17:38.882 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 17: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 8
2019-01-12 20:17:38.885 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-01-12 20:17:38.888 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 17: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 8
2019-01-12 20:17:38.890 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 17: (Callback 8)
2019-01-12 20:17:38.893 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-01-12 20:17:38.896 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 17: callback 8
2019-01-12 20:17:38.899 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=1, callback=8, payload=08 01 00 00 
2019-01-12 20:17:38.901 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
2019-01-12 20:17:38.940 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeSent, new event IncludeStart
2019-01-12 20:17:38.943 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 17: Transaction COMPLETED
2019-01-12 20:17:38.946 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 80ms
2019-01-12 20:17:38.948 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 17: Transaction completed
2019-01-12 20:17:38.951 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:17 DONE
2019-01-12 20:17:38.955 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-12 20:17:38.957 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-12 20:17:40.872 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery completed
2019-01-12 20:17:40.907 [WARN ] [wave.discovery.ZWaveDiscoveryService] - NODE 3: Device discovery could not resolve to a thingType! Manufacturer data not known.
2019-01-12 20:17:40.913 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:e74f9ee6:node3' to inbox.
2019-01-12 20:17:43.557 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 1fa1e9e1-3a7b-4984-861f-041cd7f1b1ca, base URL = http://localhost:8080)
2019-01-12 20:17:51.267 [DEBUG] [org.openhab.binding.zwave           ] - ServiceEvent REGISTERED - {org.eclipse.smarthome.config.core.status.ConfigStatusProvider}={service.id=427, service.bundleid=224, service.scope=singleton} - org.openhab.binding.zwave
2019-01-12 20:17:51.284 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - Initializing ZWave thing handler zwave:device:e74f9ee6:node3.
2019-01-12 20:17:51.323 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: MANUFACTURER not set
2019-01-12 20:17:51.326 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller status changed to ONLINE.
2019-01-12 20:17:51.329 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Controller is ONLINE. Starting device initialisation.
2019-01-12 20:17:51.345 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties.
2019-01-12 20:17:51.364 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Updating node properties. MAN=2147483647
2019-01-12 20:17:51.366 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Properties synchronised
2019-01-12 20:17:51.382 [DEBUG] [ve.internal.protocol.ZWaveController] - Event listener added.
2019-01-12 20:17:51.385 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Initialising Thing Node...
2019-01-12 20:17:51.387 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling intialised at 1800 seconds - start in 9000 milliseconds.
2019-01-12 20:17:51.389 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Device initialisation complete.
2019-01-12 20:18:00.388 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling...
2019-01-12 20:18:00.390 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling deferred until initialisation complete
2019-01-12 20:19:08.820 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - ZWave discovery: Stop zwave:serial_zstick:e74f9ee6
2019-01-12 20:19:08.825 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller stopping inclusion at IncludeStart
2019-01-12 20:19:08.829 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2019-01-12 20:19:08.833 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 18 to queue - size 1
2019-01-12 20:19:08.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-12 20:19:08.842 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 09 BC 
2019-01-12 20:19:08.848 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 09 BC 
2019-01-12 20:19:08.852 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-01-12 20:19:08.854 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-01-12 20:19:08.861 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-12 20:19:08.863 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 18: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 9
2019-01-12 20:19:08.873 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-12 20:19:08.876 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 18: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 9
2019-01-12 20:19:08.878 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-01-12 20:19:08.880 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-12 20:19:08.883 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-12 20:19:08.941 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 09 06 00 00 BD 
2019-01-12 20:19:08.946 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=9, payload=09 06 00 00 
2019-01-12 20:19:08.948 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=9, payload=09 06 00 00 
2019-01-12 20:19:08.957 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 18: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 9
2019-01-12 20:19:08.960 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-01-12 20:19:08.962 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 18: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 9
2019-01-12 20:19:08.964 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 18: (Callback 9)
2019-01-12 20:19:08.966 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-01-12 20:19:08.968 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 18: callback 9
2019-01-12 20:19:08.971 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=AddNodeToNetwork[74], type=Request[0], dest=6, callback=9, payload=09 06 00 00 
2019-01-12 20:19:08.973 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Done.
2019-01-12 20:19:08.975 [DEBUG] [al.protocol.ZWaveInclusionController] - Inclusion event: Current state IncludeDone, new event IncludeDone
2019-01-12 20:19:08.977 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Ending INCLUSION mode.
2019-01-12 20:19:08.979 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 19 to queue - size 1
2019-01-12 20:19:08.981 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-12 20:19:08.983 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave controller end exclusion
2019-01-12 20:19:08.986 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWaveController include done
2019-01-12 20:19:08.988 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 18: Advanced to DONE
2019-01-12 20:19:08.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 134ms
2019-01-12 20:19:08.992 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 18: Transaction completed
2019-01-12 20:19:08.994 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:18 DONE
2019-01-12 20:19:08.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-12 20:19:09.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-12 20:19:09.003 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 05 00 B5 
2019-01-12 20:19:09.006 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 05 00 B5 
2019-01-12 20:19:09.008 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-01-12 20:19:09.010 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-01-12 20:19:09.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 19: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2019-01-12 20:19:09.012 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-12 20:19:09.014 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-01-12 20:19:09.016 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 19: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 0
2019-01-12 20:19:09.018 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-01-12 20:19:09.020 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-12 20:19:09.021 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-01-12 20:19:14.012 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 19: Timeout at state WAIT_REQUEST. 3 retries remaining.
2019-01-12 20:19:14.014 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 19: Transaction is current transaction, so clearing!!!!!
2019-01-12 20:19:14.015 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 19: Transaction CANCELLED
2019-01-12 20:19:14.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:19 CANCELLED
2019-01-12 20:19:14.025 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-12 20:23:07.898 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1E 00 49 84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 F4 
2019-01-12 20:23:07.911 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 
2019-01-12 20:23:07.917 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 
2019-01-12 20:23:07.920 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-01-12 20:23:07.923 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2019-01-12 20:23:07.925 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2019-01-12 20:23:07.931 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 
2019-01-12 20:23:07.934 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 3: Application update request. Node information received. Transaction null
2019-01-12 20:23:07.937 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 3: Application update - no transaction.
2019-01-12 20:23:07.940 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-12 20:23:07.943 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-12 20:27:10.346 [WARN ] [shd.server.session.ServerSessionImpl] - exceptionCaught(ServerSessionImpl[openhab@/127.0.0.1:48532])[state=Opened] InterruptedByTimeoutException: null
2019-01-12 20:29:14.640 [DEBUG] [al.protocol.ZWaveInclusionController] - ZWave inclusion controller finalised
2019-01-12 20:42:12.076 [WARN ] [sitemap.internal.SitemapProviderImpl] - Filename `energy.sitemap` does not match the name `main` of the sitemap - please fix this as you might see unexpected behavior otherwise.
2019-01-12 20:42:12.119 [WARN ] [sitemap.internal.SitemapProviderImpl] - Filename `energy.sitemap` does not match the name `main` of the sitemap - please fix this as you might see unexpected behavior otherwise.
2019-01-12 20:44:05.115 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1E 00 49 84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 F4 
2019-01-12 20:44:05.139 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 
2019-01-12 20:44:05.150 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 
2019-01-12 20:44:05.154 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-01-12 20:44:05.157 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2019-01-12 20:44:05.161 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2019-01-12 20:44:05.175 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 
2019-01-12 20:44:05.179 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 3: Application update request. Node information received. Transaction null
2019-01-12 20:44:05.182 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 3: Application update - no transaction.
2019-01-12 20:44:05.186 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-12 20:44:05.190 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-12 20:48:00.388 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling...
2019-01-12 20:48:03.400 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling deferred until initialisation complete
2019-01-12 20:48:26.725 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1E 00 49 84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 F4 
2019-01-12 20:48:26.771 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 
2019-01-12 20:48:26.780 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 
2019-01-12 20:48:26.784 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-01-12 20:48:26.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2019-01-12 20:48:26.791 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2019-01-12 20:48:26.799 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 
2019-01-12 20:48:26.802 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 3: Application update request. Node information received. Transaction null
2019-01-12 20:48:26.805 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 3: Application update - no transaction.
2019-01-12 20:48:26.808 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-12 20:48:26.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-12 20:58:17.618 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1E 00 49 84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 F4 
2019-01-12 20:58:17.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 
2019-01-12 20:58:17.637 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 
2019-01-12 20:58:17.639 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-01-12 20:58:17.640 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2019-01-12 20:58:17.643 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2019-01-12 20:58:17.648 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 
2019-01-12 20:58:17.650 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 3: Application update request. Node information received. Transaction null
2019-01-12 20:58:17.653 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 3: Application update - no transaction.
2019-01-12 20:58:17.656 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-12 20:58:17.658 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-12 21:00:00.103 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest executed...
2019-01-12 21:00:05.863 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:e74f9ee6
2019-01-12 21:00:32.747 [INFO ] [arthome.model.script.speedtest.rules] - --> speedtest finished.
2019-01-12 21:02:40.785 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update received
2019-01-12 21:02:40.791 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update set action_heal to true (Boolean)
2019-01-12 21:02:40.795 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Starting heal on node!
2019-01-12 21:02:40.799 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Can not start heal as initialisation is not complete (SECURITY_REPORT).
2019-01-12 21:02:40.802 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update set binding_cmdrepollperiod to 1500 (BigDecimal)
2019-01-12 21:02:40.806 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update set action_failed to false (Boolean)
2019-01-12 21:02:40.809 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update set action_remove to false (Boolean)
2019-01-12 21:02:40.814 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update set binding_pollperiod to 86400 (BigDecimal)
2019-01-12 21:02:40.817 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling intialised at 86400 seconds - start in 8726400 milliseconds.
2019-01-12 21:02:40.821 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored node_id to 3 (BigDecimal)
2019-01-12 21:04:21.398 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update received
2019-01-12 21:04:21.402 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored action_heal to false (Boolean)
2019-01-12 21:04:21.405 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored binding_cmdrepollperiod to 1500 (BigDecimal)
2019-01-12 21:04:21.409 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored action_failed to false (Boolean)
2019-01-12 21:04:21.412 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored action_remove to false (Boolean)
2019-01-12 21:04:21.415 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update set binding_pollperiod to 600 (BigDecimal)
2019-01-12 21:04:21.418 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling intialised at 600 seconds - start in 53400 milliseconds.
2019-01-12 21:04:21.421 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored node_id to 3 (BigDecimal)
2019-01-12 21:05:14.819 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling...
2019-01-12 21:05:14.824 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling deferred until initialisation complete
2019-01-12 21:05:47.391 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update received
2019-01-12 21:05:47.399 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored action_heal to false (Boolean)
2019-01-12 21:05:47.403 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored binding_cmdrepollperiod to 1500 (BigDecimal)
2019-01-12 21:05:47.409 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored action_failed to false (Boolean)
2019-01-12 21:05:47.413 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored action_remove to false (Boolean)
2019-01-12 21:05:47.419 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update set binding_pollperiod to 86400 (BigDecimal)
2019-01-12 21:05:47.424 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling intialised at 86400 seconds - start in 43286400 milliseconds.
2019-01-12 21:05:47.429 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored node_id to 3 (BigDecimal)
2019-01-12 21:06:10.030 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1E 00 49 84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 F4 
2019-01-12 21:06:10.041 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 
2019-01-12 21:06:10.047 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 
2019-01-12 21:06:10.050 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-01-12 21:06:10.052 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0
2019-01-12 21:06:10.055 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null
2019-01-12 21:06:10.060 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 
2019-01-12 21:06:10.063 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 3: Application update request. Node information received. Transaction null
2019-01-12 21:06:10.065 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 3: Application update - no transaction.
2019-01-12 21:06:10.068 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-12 21:06:10.070 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

(Joan Pujol) #6

I attach more log:

At 2019-01-14 09:20:37.625 some command classes are processed

And at 2019-01-13 20:11:15 it seems that there is some advance in the initialization:

2019-01-13 20:11:15.835 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 52: Transaction completed
2019-01-13 20:11:15.836 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:52 DONE
2019-01-13 20:11:15.839 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-01-13 20:11:15.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 52: Transaction event listener: DONE: DONE -&gt;
2019-01-13 20:11:15.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-01-13 20:11:15.852 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@13800d4
2019-01-13 20:11:15.853 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-01-13 20:11:15.854 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE
2019-01-13 20:11:15.856 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to SECURITY_REPORT

It’s quite clear to me that the problem is that initialization isn’t completed. But why? What I can do for it to complete?
It seems that more than I can get is `Node advancer - advancing to SECURITY_REPORT, what’s this state?

Complete log from prior day:

2019-01-13 20:11:15.795 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_ALARM to the list of supported command classes.

2019-01-13 20:11:15.796 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_SECURITY

2019-01-13 20:11:15.800 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SECURITY, endpoint 0 created

2019-01-13 20:11:15.804 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_SECURITY to the list of supported command classes.

2019-01-13 20:11:15.805 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_FIRMWARE_UPDATE_MD

2019-01-13 20:11:15.808 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_FIRMWARE_UPDATE_MD, endpoint 0 created

2019-01-13 20:11:15.811 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_FIRMWARE_UPDATE_MD to the list of supported command classes.

2019-01-13 20:11:15.812 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_CENTRAL_SCENE

2019-01-13 20:11:15.816 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_CENTRAL_SCENE, endpoint 0 created

2019-01-13 20:11:15.819 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_CENTRAL_SCENE to the list of supported command classes.

2019-01-13 20:11:15.820 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_SWITCH_MULTILEVEL

2019-01-13 20:11:15.824 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0 created

2019-01-13 20:11:15.827 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_SWITCH_MULTILEVEL to the list of supported command classes.

2019-01-13 20:11:15.832 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 52: Advanced to DONE

2019-01-13 20:11:15.833 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Response processed after 258ms

2019-01-13 20:11:15.835 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 52: Transaction completed

2019-01-13 20:11:15.836 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:52 DONE

2019-01-13 20:11:15.839 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2019-01-13 20:11:15.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 52: Transaction event listener: DONE: DONE -&gt;

2019-01-13 20:11:15.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-13 20:11:15.852 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@13800d4

2019-01-13 20:11:15.853 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-13 20:11:15.854 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE

2019-01-13 20:11:15.856 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to SECURITY_REPORT

2019-01-13 20:11:15.857 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveInitializationStateEvent

2019-01-13 21:38:49.883 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:e74f9ee6

2019-01-13 21:42:26.967 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1E 00 49 84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 F4

2019-01-13 21:42:26.979 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0&lt;&gt;128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26

2019-01-13 21:42:26.983 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26

2019-01-13 21:42:26.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2019-01-13 21:42:26.988 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0

2019-01-13 21:42:26.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null

2019-01-13 21:42:26.996 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26

2019-01-13 21:42:27.004 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-13 21:42:27.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-13 21:47:47.059 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - getConfigDescriptions called

2019-01-13 21:49:17.370 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - No bridgeUID found in getConfigDescription thing:zwave:serial_zstick:e74f9ee6

2019-01-13 21:50:58.500 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update received

2019-01-13 21:50:58.582 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update set action_heal to true (Boolean)

2019-01-13 21:50:58.585 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Starting heal on node!

2019-01-13 21:50:58.588 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Can not start heal as initialisation is not complete (SECURITY_REPORT).

2019-01-13 21:50:58.592 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored binding_cmdrepollperiod to 1500 (BigDecimal)

2019-01-13 21:50:58.595 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored action_failed to false (Boolean)

2019-01-13 21:50:58.598 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored action_remove to false (Boolean)

2019-01-13 21:50:58.601 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored binding_pollperiod to 86400 (BigDecimal)

2019-01-13 21:50:58.605 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Configuration update ignored node_id to 3 (BigDecimal)

2019-01-13 23:23:19.402 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1E 00 49 84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 F4

2019-01-13 23:23:19.431 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0&lt;&gt;128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26

2019-01-13 23:23:19.443 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26

2019-01-13 23:23:19.448 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2019-01-13 23:23:19.451 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0

2019-01-13 23:23:19.455 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null

2019-01-13 23:23:19.462 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26

2019-01-13 23:23:19.471 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-13 23:23:19.474 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-14 00:02:20.164 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 1E 00 49 84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26 F4

2019-01-14 00:02:20.211 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0&lt;&gt;128 : Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26

2019-01-14 00:02:20.220 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26

2019-01-14 00:02:20.225 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2019-01-14 00:02:20.228 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0

2019-01-14 00:02:20.230 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null

2019-01-14 00:02:20.238 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=ApplicationUpdate[73], type=Request[0], dest=3, callback=132, payload=84 03 18 04 10 01 5E 86 72 25 5A 59 85 73 56 70 32 8E 60 22 75 71 98 7A 5B EF 26

2019-01-14 00:02:20.250 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-14 00:02:20.253 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-14 03:43:34.480 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Starting network mesh heal for controller zwave:serial_zstick:e74f9ee6.

2019-01-14 03:43:34.486 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Starting network mesh heal for controller zwave:serial_zstick:e74f9ee6.

2019-01-14 03:43:34.492 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Starting network mesh heal.

2019-01-14 03:43:34.497 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Starting initialisation from HEAL_START

2019-01-14 03:43:34.504 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Starting network mesh heal for controller zwave:serial_zstick:e74f9ee6.

2019-01-14 03:43:34.509 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to HEAL_START

2019-01-14 03:43:34.515 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to UPDATE_NEIGHBORS

2019-01-14 03:43:34.517 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Can not start heal as initialisation is not complete (SECURITY_REPORT).

2019-01-14 03:43:34.520 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer: UPDATE_NEIGHBORS - updating neighbor list

2019-01-14 03:43:34.528 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@1bbb666

2019-01-14 03:43:34.542 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: Adding to device queue

2019-01-14 03:43:34.544 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: Added 53 to queue - size 1

2019-01-14 03:43:34.546 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-14 03:43:34.551 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 48 01 80 33

2019-01-14 03:43:34.560 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-01-14 03:43:34.561 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2019-01-14 03:43:34.562 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 53: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 128

2019-01-14 03:43:34.564 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0&lt;&gt;128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-01-14 03:43:34.566 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-01-14 03:43:34.570 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 53: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 128

2019-01-14 03:43:34.573 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2019-01-14 03:43:34.576 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-14 03:43:34.579 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-01-14 03:43:34.722 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 80 21 13

2019-01-14 03:43:34.726 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0&lt;&gt;128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=33, callback=128, payload=80 21

2019-01-14 03:43:34.728 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=33, callback=128, payload=80 21

2019-01-14 03:43:34.731 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 53: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 128

2019-01-14 03:43:34.734 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-01-14 03:43:34.737 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 53: [WAIT_REQUEST] priority=Controller, requiresResponse=true, callback: 128

2019-01-14 03:43:34.740 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 53: (Callback 128)

2019-01-14 03:43:34.741 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!

2019-01-14 03:43:34.743 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 53: callback 128

2019-01-14 03:43:34.745 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=33, callback=128, payload=80 21

2019-01-14 03:43:34.752 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 53: Advanced to DONE

2019-01-14 03:43:34.753 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: Response processed after 191ms

2019-01-14 03:43:34.755 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: TID 53: Transaction completed

2019-01-14 03:43:34.756 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 1: notifyTransactionResponse TID:53 DONE

2019-01-14 03:43:34.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-14 03:43:34.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 53: Transaction event listener: DONE: DONE -&gt;

2019-01-14 03:43:34.762 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-14 03:43:34.766 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@143dd16

2019-01-14 03:43:34.768 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init transaction completed with response COMPLETE

2019-01-14 03:43:34.772 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to GET_NEIGHBORS

2019-01-14 03:43:34.775 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer: GET_NEIGHBORS - get RoutingInfo

2019-01-14 03:43:34.782 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@415f5a

2019-01-14 03:43:34.785 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added 54 to queue - size 1

2019-01-14 03:43:34.788 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-14 03:43:34.796 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 07 00 80 01 00 00 03 7A

2019-01-14 03:43:34.799 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT

2019-01-14 03:43:34.801 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06

2019-01-14 03:43:34.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0&lt;&gt;128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-01-14 03:43:34.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 54: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0

2019-01-14 03:43:34.806 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=

2019-01-14 03:43:34.807 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2019-01-14 03:43:34.809 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK

2019-01-14 03:43:34.811 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 20 01 80 04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 5A

2019-01-14 03:43:34.812 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-14 03:43:34.813 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.

2019-01-14 03:43:34.837 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0&lt;&gt;128 : Message: class=GetRoutingInfo[128], type=Response[1], dest=255, callback=0, payload=04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

2019-01-14 03:43:34.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=GetRoutingInfo[128], type=Response[1], dest=255, callback=0, payload=04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

2019-01-14 03:43:34.844 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 54: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0

2019-01-14 03:43:34.846 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1

2019-01-14 03:43:34.848 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 54: [WAIT_RESPONSE] priority=Controller, requiresResponse=true, callback: 0

2019-01-14 03:43:34.852 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=GetRoutingInfo[128], type=Response[1], dest=255, callback=0, payload=04 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

2019-01-14 03:43:34.880 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 54: Transaction COMPLETED

2019-01-14 03:43:34.881 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 79ms

2019-01-14 03:43:34.883 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 54: Transaction completed

2019-01-14 03:43:34.884 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:54 DONE

2019-01-14 03:43:34.888 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-14 03:43:34.888 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 54: Transaction event listener: DONE: DONE -&gt;

2019-01-14 03:43:34.890 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-14 03:43:34.890 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@7fd532

2019-01-14 03:43:34.892 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node Init transaction completed with response COMPLETE

2019-01-14 03:43:34.894 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to DELETE_SUC_ROUTES

2019-01-14 03:43:34.896 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to SUC_ROUTE

2019-01-14 03:43:34.897 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to DELETE_ROUTES

2019-01-14 03:43:34.900 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Generate return routes list

2019-01-14 03:43:34.901 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Node is not a routing node. No routes can be set.

2019-01-14 03:43:34.905 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to RETURN_ROUTES

2019-01-14 03:43:34.907 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Generate return routes list

2019-01-14 03:43:34.909 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 1: Node is not a routing node. No routes can be set.

2019-01-14 03:43:34.911 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to HEAL_END

2019-01-14 03:43:34.913 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Serializing to file /var/lib/openhab2/zwave/network_ed074673__node_1.xml

2019-01-14 03:43:34.924 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 1: Node advancer - advancing to DONE

2019-01-14 03:43:34.927 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 1: Serializing to file /var/lib/openhab2/zwave/network_ed074673__node_1.xml

2019-01-14 03:43:42.662 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 05 00 48 80 23 11

2019-01-14 03:43:42.665 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0&lt;&gt;128 : Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=128, payload=80 23

2019-01-14 03:43:42.668 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=128, payload=80 23

2019-01-14 03:43:42.670 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null

2019-01-14 03:43:42.672 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 0

2019-01-14 03:43:42.674 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: null

2019-01-14 03:43:42.676 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=RequestNodeNeighborUpdate[72], type=Request[0], dest=35, callback=128, payload=80 23

2019-01-14 03:43:42.679 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-14 03:43:42.681 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-14 08:23:59.082 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling...

2019-01-14 08:23:59.087 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling deferred until initialisation complete

2019-01-14 09:20:37.587 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_SWITCH_MULTILEVEL

2019-01-14 09:20:37.591 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0 created

2019-01-14 09:20:37.594 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_SWITCH_MULTILEVEL to the list of supported command classes.

2019-01-14 09:20:37.600 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 10: Advanced to DONE

2019-01-14 09:20:37.601 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Response processed after 261ms

2019-01-14 09:20:37.603 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 10: Transaction completed

2019-01-14 09:20:37.604 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:10 DONE

2019-01-14 09:20:37.609 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent

2019-01-14 09:20:37.611 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-14 09:20:37.615 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 10: Transaction event listener: DONE: DONE -&gt;

2019-01-14 09:20:37.619 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-14 09:20:37.625 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1bd6ecb

2019-01-14 09:20:37.628 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE

2019-01-14 09:20:37.632 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to SECURITY_REPORT

2019-01-14 09:20:37.635 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Got an event from Z-Wave network: ZWaveInitializationStateEvent

2019-01-14 10:40:57.931 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_ZWAVEPLUS_INFO to the list of supported command classes.

2019-01-14 10:40:57.933 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_VERSION

2019-01-14 10:40:57.936 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_VERSION, endpoint 0 created

2019-01-14 10:40:57.940 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_VERSION to the list of supported command classes.

2019-01-14 10:40:57.941 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_MANUFACTURER_SPECIFIC

2019-01-14 10:40:57.946 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_MANUFACTURER_SPECIFIC, endpoint 0 created

2019-01-14 10:40:57.949 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_MANUFACTURER_SPECIFIC to the list of supported command classes.

2019-01-14 10:40:57.951 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_SWITCH_BINARY

2019-01-14 10:40:57.954 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SWITCH_BINARY, endpoint 0 created

2019-01-14 10:40:57.957 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_SWITCH_BINARY to the list of supported command classes.

2019-01-14 10:40:57.959 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_DEVICE_RESET_LOCALLY

2019-01-14 10:40:57.961 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_DEVICE_RESET_LOCALLY, endpoint 0 created

2019-01-14 10:40:57.964 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_DEVICE_RESET_LOCALLY to the list of supported command classes.

2019-01-14 10:40:57.966 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_ASSOCIATION_GRP_INFO

2019-01-14 10:40:57.969 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_ASSOCIATION_GRP_INFO, endpoint 0 created

2019-01-14 10:40:57.973 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_ASSOCIATION_GRP_INFO to the list of supported command classes.

2019-01-14 10:40:57.974 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_ASSOCIATION

2019-01-14 10:40:57.978 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_ASSOCIATION, endpoint 0 created

2019-01-14 10:40:57.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_ASSOCIATION to the list of supported command classes.

2019-01-14 10:40:57.984 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_POWERLEVEL

2019-01-14 10:40:57.987 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_POWERLEVEL, endpoint 0 created

2019-01-14 10:40:57.990 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_POWERLEVEL to the list of supported command classes.

2019-01-14 10:40:57.991 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_CRC_16_ENCAP

2019-01-14 10:40:57.994 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_CRC_16_ENCAP, endpoint 0 created

2019-01-14 10:40:57.997 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_CRC_16_ENCAP to the list of supported command classes.

2019-01-14 10:40:57.999 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_CONFIGURATION

2019-01-14 10:40:58.003 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_CONFIGURATION, endpoint 0 created

2019-01-14 10:40:58.007 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_CONFIGURATION to the list of supported command classes.

2019-01-14 10:40:58.009 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_METER

2019-01-14 10:40:58.014 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_METER, endpoint 0 created

2019-01-14 10:40:58.018 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_METER to the list of supported command classes.

2019-01-14 10:40:58.020 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION

2019-01-14 10:40:58.024 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION, endpoint 0 created

2019-01-14 10:40:58.027 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION to the list of supported command classes.

2019-01-14 10:40:58.029 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_MULTI_CHANNEL

2019-01-14 10:40:58.033 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_MULTI_CHANNEL, endpoint 0 created

2019-01-14 10:40:58.036 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_MULTI_CHANNEL to the list of supported command classes.

2019-01-14 10:40:58.038 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_APPLICATION_STATUS

2019-01-14 10:40:58.041 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_APPLICATION_STATUS, endpoint 0 created

2019-01-14 10:40:58.044 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_APPLICATION_STATUS to the list of supported command classes.

2019-01-14 10:40:58.045 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_PROTECTION

2019-01-14 10:40:58.049 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_PROTECTION, endpoint 0 created

2019-01-14 10:40:58.052 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_PROTECTION to the list of supported command classes.

2019-01-14 10:40:58.053 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_ALARM

2019-01-14 10:40:58.057 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_ALARM, endpoint 0 created

2019-01-14 10:40:58.060 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_ALARM to the list of supported command classes.

2019-01-14 10:40:58.062 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_SECURITY

2019-01-14 10:40:58.066 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SECURITY, endpoint 0 created

2019-01-14 10:40:58.069 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_SECURITY to the list of supported command classes.

2019-01-14 10:40:58.071 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_FIRMWARE_UPDATE_MD

2019-01-14 10:40:58.073 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_FIRMWARE_UPDATE_MD, endpoint 0 created

2019-01-14 10:40:58.079 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_FIRMWARE_UPDATE_MD to the list of supported command classes.

2019-01-14 10:40:58.081 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_CENTRAL_SCENE

2019-01-14 10:40:58.086 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_CENTRAL_SCENE, endpoint 0 created

2019-01-14 10:40:58.090 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_CENTRAL_SCENE to the list of supported command classes.

2019-01-14 10:40:58.092 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_SWITCH_MULTILEVEL

2019-01-14 10:40:58.098 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0 created

2019-01-14 10:40:58.100 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_SWITCH_MULTILEVEL to the list of supported command classes.

2019-01-14 10:40:58.104 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 21: Advanced to DONE

2019-01-14 10:40:58.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Response processed after 243ms

2019-01-14 10:40:58.108 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 21: Transaction completed

2019-01-14 10:40:58.110 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:21 DONE

2019-01-14 10:40:58.114 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-14 10:40:58.114 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 21: Transaction event listener: DONE: DONE -&gt;

2019-01-14 10:40:58.118 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1a95d15

2019-01-14 10:40:58.121 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE

2019-01-14 10:40:58.121 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-14 10:40:58.125 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to SECURITY_REPORT

2019-01-14 11:17:17.191 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - getConfigDescriptions called

2019-01-14 10:40:57.964 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_DEVICE_RESET_LOCALLY to the list of supported command classes.

2019-01-14 10:40:57.966 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_ASSOCIATION_GRP_INFO

2019-01-14 10:40:57.969 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_ASSOCIATION_GRP_INFO, endpoint 0 created

2019-01-14 10:40:57.973 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_ASSOCIATION_GRP_INFO to the list of supported command classes.

2019-01-14 10:40:57.974 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_ASSOCIATION

2019-01-14 10:40:57.978 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_ASSOCIATION, endpoint 0 created

2019-01-14 10:40:57.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_ASSOCIATION to the list of supported command classes.

2019-01-14 10:40:57.984 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_POWERLEVEL

2019-01-14 10:40:57.987 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_POWERLEVEL, endpoint 0 created

2019-01-14 10:40:57.990 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_POWERLEVEL to the list of supported command classes.

2019-01-14 10:40:57.991 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_CRC_16_ENCAP

2019-01-14 10:40:57.994 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_CRC_16_ENCAP, endpoint 0 created

2019-01-14 10:40:57.997 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_CRC_16_ENCAP to the list of supported command classes.

2019-01-14 10:40:57.999 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_CONFIGURATION

2019-01-14 10:40:58.003 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_CONFIGURATION, endpoint 0 created

2019-01-14 10:40:58.007 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_CONFIGURATION to the list of supported command classes.

2019-01-14 10:40:58.009 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_METER

2019-01-14 10:40:58.014 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_METER, endpoint 0 created

2019-01-14 10:40:58.018 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_METER to the list of supported command classes.

2019-01-14 10:40:58.020 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION

2019-01-14 10:40:58.024 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION, endpoint 0 created

2019-01-14 10:40:58.027 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION to the list of supported command classes.

2019-01-14 10:40:58.029 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_MULTI_CHANNEL

2019-01-14 10:40:58.033 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_MULTI_CHANNEL, endpoint 0 created

2019-01-14 10:40:58.036 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_MULTI_CHANNEL to the list of supported command classes.

2019-01-14 10:40:58.038 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_APPLICATION_STATUS

2019-01-14 10:40:58.041 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_APPLICATION_STATUS, endpoint 0 created

2019-01-14 10:40:58.044 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_APPLICATION_STATUS to the list of supported command classes.

2019-01-14 10:40:58.045 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_PROTECTION

2019-01-14 10:40:58.049 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_PROTECTION, endpoint 0 created

2019-01-14 10:40:58.052 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_PROTECTION to the list of supported command classes.

2019-01-14 10:40:58.053 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_ALARM

2019-01-14 10:40:58.057 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_ALARM, endpoint 0 created

2019-01-14 10:40:58.060 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_ALARM to the list of supported command classes.

2019-01-14 10:40:58.062 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_SECURITY

2019-01-14 10:40:58.066 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SECURITY, endpoint 0 created

2019-01-14 10:40:58.069 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_SECURITY to the list of supported command classes.

2019-01-14 10:40:58.071 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_FIRMWARE_UPDATE_MD

2019-01-14 10:40:58.073 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_FIRMWARE_UPDATE_MD, endpoint 0 created

2019-01-14 10:40:58.079 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_FIRMWARE_UPDATE_MD to the list of supported command classes.

2019-01-14 10:40:58.081 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_CENTRAL_SCENE

2019-01-14 10:40:58.086 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_CENTRAL_SCENE, endpoint 0 created

2019-01-14 10:40:58.090 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_CENTRAL_SCENE to the list of supported command classes.

2019-01-14 10:40:58.092 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Creating new instance of command class COMMAND_CLASS_SWITCH_MULTILEVEL

2019-01-14 10:40:58.098 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 3: Command class COMMAND_CLASS_SWITCH_MULTILEVEL, endpoint 0 created

2019-01-14 10:40:58.100 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 3: Adding command class COMMAND_CLASS_SWITCH_MULTILEVEL to the list of supported command classes.

2019-01-14 10:40:58.104 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 21: Advanced to DONE

2019-01-14 10:40:58.106 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: Response processed after 243ms

2019-01-14 10:40:58.108 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: TID 21: Transaction completed

2019-01-14 10:40:58.110 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 3: notifyTransactionResponse TID:21 DONE

2019-01-14 10:40:58.114 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty

2019-01-14 10:40:58.114 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 21: Transaction event listener: DONE: DONE -&gt;

2019-01-14 10:40:58.118 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@1a95d15

2019-01-14 10:40:58.121 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node Init transaction completed with response COMPLETE

2019-01-14 10:40:58.121 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

2019-01-14 10:40:58.125 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 3: Node advancer - advancing to SECURITY_REPORT

2019-01-14 11:17:17.191 [DEBUG] [g.zwave.internal.ZWaveConfigProvider] - getConfigDescriptions called

2019-01-14 13:23:58.464 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling...

2019-01-14 13:23:58.467 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling deferred until initialisation complete

2019-01-14 13:23:58.464 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling...

2019-01-14 13:23:58.467 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling deferred until initialisation complete

2019-01-14 13:23:58.464 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling...

2019-01-14 13:23:58.467 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling deferred until initialisation complete

2019-01-14 13:23:58.464 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling...

2019-01-14 13:23:58.467 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 3: Polling deferred until initialisation complete

(Kris K) #7

Ive had alot of issues with inculsion on devices which ARE in the database. Takes multiple attempts with the controller/device right next to each other, sometimes 2-3 goes.

I would suggest you exclude, factory reset your end device and reinclude.

If its a powered device, it should be informed off the device very quickly, even battery devices are fairly quick for me but again, it takes multiple attempts.

I’m not sure if this is a binding issue but it seems to only have happened to be in recent 2.4/2.5 snapshot versions of the zwave binding.

Just my experience.


(Joan Pujol) #8

I tried several times with any luck,
Can it be a problem with a new firmware or ZWave Plus?
Because I’ve tested with the older switch version without zwave and it was detected in secons.

Can I provide any more log that helps to diagnose the issue?


Fibaro Motion Sensor not recognized