Vision zm1701 / zm1702 support in openhab

Hi @chris

I have vision zm1701 door lock.
Is it supported in openhab…?
I am facing continuous packet dropped and node is dead issue
I will paste logs later…

Any idea about openhab support for this door lock

Thanks,
Shrikant

Which version do you use? Currently secure classes are not supported in OH2, and in OH1 you need to be running a special build of the binding to have support for security classes.

ok… when will be the support available ?
yes i am using special build for supporting door_lock command class

Well, if you’re using the special build, I assume you are using OH1? If this binding doesn’t support this lock, then it will need to be updated, but this is outside of the main branch unfortunately.

OK…
In openhab. cfg file the zwave:network key. is present , the key is used
for only devices which are included in secure mode or it is providing
security to complete Zwave network…?
What exactly it is doing…?

It’s only used for devices included in secure mode. It’s used as the key to secure the communications between the controller and secure devices.

Thanks you chris

During inclusion, is it necessary to keep distance between zwave controller and secure device a foot or less.
what will be the behavior if kept far away from zwave controller during inclusion…?

No - you don’t need it so close - it should be within a few meters (I certainly would not put it within a foot - this is not necessary, and may cause problems).

If it’s out of range of the controller, then it won’t include. If openHAB can’t communicate with the device, then it won’t be configured to work within the system.

Hi @chris ,

i am getting a log for node 11
2016-07-22 11:58:41.449 [INFO ] [.p.c.ZWaveSecurityCommandClass] - NODE 11: setupNetworkKey useSchemeZero=false

what is used of “useSchemeZero=false” for secure device…?
there is no config parameter like this in openhab.cfg.
because i am immediately getting some error logs after above log.

2016-07-22 11:58:04.083 [INFO ] [.o.core.internal.CoreActivator] - openHAB runtime has been started (v1.7.0).
2016-07-22 11:58:09.027 [INFO ] [o.o.i.s.i.DiscoveryServiceImpl] - mDNS service has been started
2016-07-22 11:58:09.186 [INFO ] [o.o.i.s.i.DiscoveryServiceImpl] - Service Discovery initialization completed.
2016-07-22 11:58:09.204 [INFO ] [.io.transport.mqtt.MqttService] - MQTT Service initialization completed.
2016-07-22 11:58:09.206 [INFO ] [o.i.t.m.i.MqttBrokerConnection] - Starting MQTT broker connection 'mosquitto'
2016-07-22 11:58:17.099 [INFO ] [penhab.io.rest.RESTApplication] - Started REST API at /rest
2016-07-22 11:58:17.350 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'wave.items'
2016-07-22 11:58:22.400 [INFO ] [.o.u.w.i.servlet.WebAppServlet] - Started Classic UI at /openhab.app
2016-07-22 11:58:28.156 [INFO ] [c.internal.ModelRepositoryImpl] - Loading model 'wave.rules'
2016-07-22 11:58:29.239 [INFO ] [.o.io.habmin.HABminApplication] - Started HABmin REST API at /services/habmin
2016-07-22 11:58:34.632 [INFO ] [.z.internal.ZWaveActiveBinding] - Update config, port = /dev/ttyACM0
2016-07-22 11:58:34.633 [INFO ] [.z.internal.ZWaveActiveBinding] - Update config, healtime = 2
2016-07-22 11:58:34.653 [INFO ] [.p.c.ZWaveSecurityCommandClass] - Update networkKey
2016-07-22 11:58:34.657 [INFO ] [.service.AbstractActiveService] - ZWave Refresh Service has been started
2016-07-22 11:58:34.745 [INFO ] [b.z.i.protocol.ZWaveController] - Starting Z-Wave controller
2016-07-22 11:58:34.747 [INFO ] [b.z.i.protocol.ZWaveController] - Z-Wave timeout is set to 5000ms. Soft reset is false.
2016-07-22 11:58:34.748 [INFO ] [b.z.i.protocol.ZWaveController] - Connecting to serial port /dev/ttyACM0
2016-07-22 11:58:34.892 [INFO ] [b.z.i.protocol.ZWaveController] - Serial port is initialized
2016-07-22 11:58:37.983 [ERROR] [b.z.i.protocol.ZWaveController] - Exception during Z-Wave thread: Input.
java.lang.NullPointerException: null
    at org.openhab.binding.zwave.internal.protocol.SerialMessage.getMessageBuffer(SerialMessage.java:215) ~[na:na]
    at org.openhab.binding.zwave.internal.protocol.ZWaveController$ZWaveInputThread.run(ZWaveController.java:1169) ~[na:na]
2016-07-22 11:58:38.166 [INFO ] [rialApiGetInitDataMessageClass] - NODE 1: Node found
2016-07-22 11:58:38.167 [INFO ] [rialApiGetInitDataMessageClass] - NODE 5: Node found
2016-07-22 11:58:38.167 [INFO ] [rialApiGetInitDataMessageClass] - NODE 11: Node found
2016-07-22 11:58:38.168 [INFO ] [rialApiGetInitDataMessageClass] - ZWave Controller using Controller API
2016-07-22 11:58:38.169 [INFO ] [rialApiGetInitDataMessageClass] - ZWave Controller is Primary Controller
2016-07-22 11:58:38.170 [INFO ] [rialApiGetInitDataMessageClass] - ------------Number of Nodes Found Registered to ZWave Controller------------
2016-07-22 11:58:38.171 [INFO ] [rialApiGetInitDataMessageClass] - # Nodes = 3
2016-07-22 11:58:38.171 [INFO ] [rialApiGetInitDataMessageClass] - ----------------------------------------------------------------------------
2016-07-22 11:58:41.449 [INFO ] [.p.c.ZWaveSecurityCommandClass] - NODE 11: setupNetworkKey useSchemeZero=false
2016-07-22 11:58:47.336 [ERROR] [WaveController$ZWaveSendThread] - NODE 11: Timeout while sending message. Requeueing - 2 attempts left!
2016-07-22 11:58:47.338 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 11: Got an error while sending data. Resending message: Message: class = SendData (0x13), type = Request (0x00), payload = 0B 02 80 02 , callbackid = 8
2016-07-22 11:58:49.663 [INFO ] [.p.c.ZWaveSecurityCommandClass] - NODE 11: Duplicate messge found, removing from payloadEncapsulationQueue: NODE 11: SecurityPayload (part 1 of 1) for BATTERY : Message: class = SendData (0x13), type = Request (0x00), payload = 80 02 
2016-07-22 11:58:54.791 [WARN ] [.i.p.c.ZWaveSecureNonceTracker] - NODE 11: Received new nonce from device, ejecting Nonce RECEIVED   22 B4 07 62 09 3F E1 5F ; time left=4942.
2016-07-22 11:58:54.868 [INFO ] [.p.c.ZWaveDoorLockCommandClass] - NODE 11: Door Lock report - lockState = 0xff,handlesMode = 0x10, doorCondition = 0x00, lockTimeoutMinutes = 0xfe,lockTimeoutSeconds = 0xfe
2016-07-22 11:59:21.850 [INFO ] [.p.c.ZWaveDoorLockCommandClass] - NODE 11: Door Lock report - lockState = 0xff,handlesMode = 0x10, doorCondition = 0x00, lockTimeoutMinutes = 0xfe,lockTimeoutSeconds = 0xfe
2016-07-22 11:59:52.697 [INFO ] [.p.c.ZWaveDoorLockCommandClass] - NODE 11: Door Lock report - lockState = 0xff,handlesMode = 0x10, doorCondition = 0x00, lockTimeoutMinutes = 0xfe,lockTimeoutSeconds = 0xfe
2016-07-22 12:00:13.696 [WARN ] [b.z.i.c.ZWaveDoorLockConverter] - NODE 11: No converter found for item = DOOR_LOCK_233_234_6_1, endpoint = 0, command =OFF
2016-07-22 12:00:15.863 [WARN ] [.i.p.c.ZWaveSecureNonceTracker] - NODE 11: Received new nonce from device, ejecting Nonce RECEIVED   65 31 07 55 E3 EE D1 18 ; time left=4902.
2016-07-22 12:00:19.677 [INFO ] [.p.c.ZWaveSecurityCommandClass] - NODE 11: Duplicate messge found, removing from payloadEncapsulationQueue: NODE 11: SecurityPayload (part 1 of 1) for DOOR_LOCK : Message: class = SendData (0x13), type = Request (0x00), payload = 62 02 
2016-07-22 12:00:20.173 [INFO ] [.p.c.ZWaveDoorLockCommandClass] - NODE 11: Door Lock report - lockState = 0x00,handlesMode = 0x10, doorCondition = 0x02, lockTimeoutMinutes = 0xfe,lockTimeoutSeconds = 0xfe
2016-07-22 12:00:25.179 [ERROR] [WaveController$ZWaveSendThread] - NODE 11: Timeout while sending message. Requeueing - 2 attempts left!
2016-07-22 12:00:25.180 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 11: Got an error while sending data. Resending message: Message: class = SendData (0x13), type = Request (0x00), payload = 0B 02 62 02 , callbackid = 29
2016-07-22 12:00:32.627 [INFO ] [.p.c.ZWaveDoorLockCommandClass] - NODE 11: Door Lock report - lockState = 0x00,handlesMode = 0x10, doorCondition = 0x02, lockTimeoutMinutes = 0xfe,lockTimeoutSeconds = 0xfe
2016-07-22 12:00:54.684 [ERROR] [WaveController$ZWaveSendThread] - NODE 11: Timeout while sending message. Requeueing - 2 attempts left!
2016-07-22 12:00:54.685 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 11: Got an error while sending data. Resending message: Message: class = SendData (0x13), type = Request (0x00), payload = 0B 02 98 40 , callbackid = 34
2016-07-22 12:00:56.805 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 11: Got an error while sending data. Resending message: Message: class = SendData (0x13), type = Request (0x00), payload = 0B 02 98 40 , callbackid = 34
2016-07-22 12:01:01.492 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 11: Got an error while sending data. Resending message: Message: class = SendData (0x13), type = Request (0x00), payload = 0B 02 62 02 , callbackid = 35
2016-07-22 12:01:03.546 [WARN ] [.i.p.c.ZWaveSecureNonceTracker] - NODE 11: nonce was received, but we have no requestNonceTimer
2016-07-22 12:01:03.547 [WARN ] [.i.p.c.ZWaveSecureNonceTracker] - NODE 11: Received new nonce from device, ejecting Nonce RECEIVED   01 DD 17 EB EA E9 F2 43 ; time left=330.
2016-07-22 12:01:03.612 [INFO ] [.p.c.ZWaveDoorLockCommandClass] - NODE 11: Door Lock report - lockState = 0x00,handlesMode = 0x10, doorCondition = 0x02, lockTimeoutMinutes = 0xfe,lockTimeoutSeconds = 0xfe
2016-07-22 12:01:03.778 [ERROR] [.i.p.c.ZWaveSecureNonceTracker] - NODE 11: Could not find nonce (probably expired) for id=0x43 in table=NonceTable: [
2016-07-22 12:01:03.780 [ERROR] [ApplicationCommandMessageClass] - NODE 11: Failed to decrypt message out of Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 0B 1B 98 81 F0 FD 52 57 29 E2 1E AF 4D BC 65 1C 9C 16 81 00 43 0A 61 43 58 9B BE 72 FA , callbackid = 0 .
2016-07-22 12:01:03.801 [ERROR] [.i.p.c.ZWaveSecureNonceTracker] - NODE 11: Could not find nonce (probably expired) for id=0x43 in table=NonceTable: [
2016-07-22 12:01:03.802 [ERROR] [ApplicationCommandMessageClass] - NODE 11: Failed to decrypt message out of Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 0B 1B 98 81 F0 FD 52 57 29 E2 1E AF 4D BC 65 1C 9C 16 81 00 43 0A 61 43 58 9B BE 72 FA , callbackid = 0 .
2016-07-22 12:01:09.485 [WARN ] [b.z.i.c.ZWaveDoorLockConverter] - NODE 11: No converter found for item = DOOR_LOCK_233_234_6_1, endpoint = 0, command =ON
2016-07-22 12:01:19.493 [ERROR] [WaveController$ZWaveSendThread] - NODE 11: Timeout while sending message. Requeueing - 2 attempts left!
2016-07-22 12:01:19.494 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 11: Got an error while sending data. Resending message: Message: class = SendData (0x13), type = Request (0x00), payload = 0B 02 98 40 , callbackid = 40
2016-07-22 12:01:19.686 [INFO ] [.p.c.ZWaveSecurityCommandClass] - NODE 11: Duplicate messge found, removing from payloadEncapsulationQueue: NODE 11: SecurityPayload (part 1 of 1) for DOOR_LOCK : Message: class = SendData (0x13), type = Request (0x00), payload = 62 02 
2016-07-22 12:01:21.595 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 11: Got an error while sending data. Resending message: Message: class = SendData (0x13), type = Request (0x00), payload = 0B 02 98 40 , callbackid = 40
2016-07-22 12:01:26.322 [ERROR] [b.z.i.p.s.SendDataMessageClass] - NODE 11: Node is DEAD. Dropping message.
2016-07-22 12:01:26.327 [WARN ] [i.p.s.IsFailedNodeMessageClass] - NODE 11: Is currently marked as failed by the controller!
2016-07-22 12:01:26.333 [WARN ] [i.p.s.IsFailedNodeMessageClass] - NODE 11: Is currently marked as failed by the controller!
2016-07-22 12:01:28.651 [WARN ] [b.z.i.p.s.SendDataMessageClass] - Node not found!

i guess there is issue with some network key, actually not getting…?
Please can you give any clue…?

Thanks,
Shrikant

Scheme0 is not a configuration option - this is stating that the binding is using Scheme0. Scheme0 is only used for the inital key exchange.

It’s hard to tell what is happening in the log as it contains no debug information…

OK…but why schemezero is false…

I don’t know - without logs it’s always hard to tell. Maybe the key has been transferred already - there’s nothing in the log that I can see that indicates that the device is being included so I would expect it NOT to use Scheme0.

Hi,
i am pasting some logs, can you check please…
i am getting continuously dead node for node 11. (vision doorlock zm1702)
12:21:09.895 [DEBUG] [.z.internal.ZWaveActiveBinding:176 ] - ConverterHandler not initialised. Polling disabled. 12:21:09.898 [INFO ] [.z.internal.ZWaveActiveBinding:330 ] - Update config, port = /dev/ttyACM0 12:21:09.900 [INFO ] [.z.internal.ZWaveActiveBinding:335 ] - Update config, healtime = 2 12:21:09.917 [INFO ] [.p.c.ZWaveSecurityCommandClass:952 ] - Update networkKey 12:21:09.919 [DEBUG] [.z.internal.ZWaveActiveBinding:283 ] - Initialising zwave binding 12:21:09.922 [INFO ] [.service.AbstractActiveService:169 ] - ZWave Refresh Service has been started 12:21:09.984 [INFO ] [b.z.i.protocol.ZWaveController:152 ] - Starting Z-Wave controller 12:21:09.985 [INFO ] [b.z.i.protocol.ZWaveController:160 ] - Z-Wave timeout is set to 5000ms. Soft reset is false. 12:21:09.987 [INFO ] [b.z.i.protocol.ZWaveController:326 ] - Connecting to serial port /dev/ttyACM0 12:21:10.196 [DEBUG] [eController$ZWaveReceiveThread:1439 ] - Starting Z-Wave thread: Receive 12:21:10.203 [DEBUG] [WaveController$ZWaveSendThread:1206 ] - Starting Z-Wave thread: Send 12:21:10.207 [DEBUG] [b.z.i.protocol.ZWaveController:1159 ] - Starting Z-Wave thread: Input 12:21:10.207 [INFO ] [b.z.i.protocol.ZWaveController:348 ] - Serial port is initialized 12:21:13.212 [DEBUG] [veController$WatchDogTimerTask:182 ] - Initialising network 12:21:13.229 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 255: Creating empty message of class = GetVersion (0x15), type = Request (0x00) 12:21:13.231 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 0 12:21:13.231 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 0 12:21:13.235 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 03 00 15 E9 12:21:13.235 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 255: Creating empty message of class = MemoryGetId (0x20), type = Request (0x00) 12:21:13.236 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 1 12:21:13.237 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 255: Sending REQUEST Message = Message: class = GetVersion (0x15), type = Request (0x00), payload = , callbackid = 0 12:21:13.241 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 255: Creating empty message of class = SerialApiGetCapabilities (0x07), type = Request (0x00) 12:21:13.243 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 2 12:21:13.246 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 255: Creating empty message of class = SerialApiSetTimeouts (0x06), type = Request (0x00) 12:21:13.247 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 33 2E 39 39 00 01 95 12:21:13.248 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 3 12:21:13.250 [DEBUG] [i.p.s.GetSucNodeIdMessageClass:30 ] - Get SUC NodeID 12:21:13.252 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 255: Creating empty message of class = GetSucNodeId (0x56), type = Request (0x00) 12:21:13.253 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 4 12:21:13.257 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:13.259 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=0 12:21:13.261 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 10 01 15 5A 2D 57 61 76 65 20 33 2E 39 39 00 01 95 12:21:13.264 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 10 01 15 5A 2D 57 61 76 65 20 33 2E 39 39 00 01 95 12:21:13.267 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = GetVersion (0x15), type = Response (0x01), payload = 5A 2D 57 61 76 65 20 33 2E 39 39 00 01 , callbackid = 0 12:21:13.292 [DEBUG] [z.i.p.s.GetVersionMessageClass:39 ] - Got MessageGetVersion response. Version = Z-Wave 3.99, Library Type = 0x01 12:21:13.294 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74 ] - Sent message Message: class = GetVersion (0x15), type = Request (0x00), payload = , callbackid = 0 12:21:13.298 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ] - Recv message Message: class = GetVersion (0x15), type = Response (0x01), payload = 5A 2D 57 61 76 65 20 33 2E 39 39 00 01 , callbackid = 0 12:21:13.300 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:88 ] - Checking transaction complete: class=GetVersion, callback id=0, expected=GetVersion, cancelled=false transaction complete! 12:21:13.303 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = GetVersion (0x15), type = Request (0x00), payload = , callbackid = 0, state=true] 12:21:13.305 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = GetVersion (0x15), type = Request (0x00), payload = , callbackid = 0, state=true] 12:21:13.311 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 255: Processing event ourselves 12:21:13.313 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 255: Response processed for callback id 0 after 74ms/74ms. 12:21:13.314 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 3 12:21:13.316 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 03 00 20 DC 12:21:13.318 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 255: Sending REQUEST Message = Message: class = MemoryGetId (0x20), type = Request (0x00), payload = , callbackid = 0 12:21:13.322 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 08 01 20 0E 0D 0C 0B 01 D3 12:21:13.325 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:13.325 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:13.327 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 08 01 20 0E 0D 0C 0B 01 D3 12:21:13.329 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 08 01 20 0E 0D 0C 0B 01 D3 12:21:13.331 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = MemoryGetId (0x20), type = Response (0x01), payload = 0E 0D 0C 0B 01 , callbackid = 0 12:21:13.333 [DEBUG] [.i.p.s.MemoryGetIdMessageClass:41 ] - Got MessageMemoryGetId response. Home id = 0x0E0D0C0B, Controller Node id = 1 12:21:13.335 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74 ] - Sent message Message: class = MemoryGetId (0x20), type = Request (0x00), payload = , callbackid = 0 12:21:13.337 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ] - Recv message Message: class = MemoryGetId (0x20), type = Response (0x01), payload = 0E 0D 0C 0B 01 , callbackid = 0 12:21:13.338 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:88 ] - Checking transaction complete: class=MemoryGetId, callback id=0, expected=MemoryGetId, cancelled=false transaction complete! 12:21:13.340 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = MemoryGetId (0x20), type = Request (0x00), payload = , callbackid = 0, state=true] 12:21:13.341 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = MemoryGetId (0x20), type = Request (0x00), payload = , callbackid = 0, state=true] 12:21:13.343 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 255: Processing event ourselves 12:21:13.344 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 255: Response processed for callback id 0 after 25ms/74ms. 12:21:13.346 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 2 12:21:13.348 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 03 00 07 FB 12:21:13.349 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 255: Sending REQUEST Message = Message: class = SerialApiGetCapabilities (0x07), type = Request (0x00), payload = , callbackid = 0 12:21:13.360 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 2B 01 07 05 02 01 15 04 00 00 01 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 09 12:21:13.370 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:13.370 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:13.378 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 2B 01 07 05 02 01 15 04 00 00 01 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 09 12:21:13.385 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 2B 01 07 05 02 01 15 04 00 00 01 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 09 12:21:13.391 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = SerialApiGetCapabilities (0x07), type = Response (0x01), payload = 05 02 01 15 04 00 00 01 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 , callbackid = 0 12:21:13.394 [DEBUG] [ApiGetCapabilitiesMessageClass:45 ] - API Version = 5.2 12:21:13.395 [DEBUG] [ApiGetCapabilitiesMessageClass:46 ] - Manufacture ID = 0x115 12:21:13.397 [DEBUG] [ApiGetCapabilitiesMessageClass:47 ] - Device Type = 0x400 12:21:13.398 [DEBUG] [ApiGetCapabilitiesMessageClass:48 ] - Device ID = 0x1 12:21:13.400 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: SerialApiGetInitData 12:21:13.402 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: SerialApiApplicationNodeInfo 12:21:13.403 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: ApplicationCommandHandler 12:21:13.404 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: GetControllerCapabilities 12:21:13.406 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: SerialApiSetTimeouts 12:21:13.407 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: SerialApiGetCapabilities 12:21:13.409 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: SerialApiSoftReset 12:21:13.410 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0x09 12:21:13.412 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0x0a 12:21:13.413 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: RfReceiveMode 12:21:13.414 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: SetSleepMode 12:21:13.416 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: SendNodeInfo 12:21:13.417 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: SendData 12:21:13.418 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: SendDataMulti 12:21:13.420 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: GetVersion 12:21:13.421 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: SendDataAbort 12:21:13.422 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: RfPowerLevelSet 12:21:13.423 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: SendDataMeta 12:21:13.425 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: GetRandom 12:21:13.426 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: MemoryGetId 12:21:13.428 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: MemoryGetByte 12:21:13.429 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: MemoryPutByte 12:21:13.430 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: ReadMemory 12:21:13.431 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: WriteMemory 12:21:13.433 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0x27 12:21:13.435 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0x28 12:21:13.436 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0x29 12:21:13.438 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0x2a 12:21:13.439 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0x2b 12:21:13.440 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0x2c 12:21:13.441 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0x2d 12:21:13.442 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: IdentifyNode 12:21:13.443 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: SetDefault 12:21:13.444 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: ReplicationCommandComplete 12:21:13.446 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: ReplicationSendData 12:21:13.447 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: AssignReturnRoute 12:21:13.448 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: DeleteReturnRoute 12:21:13.449 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: RequestNodeNeighborUpdate 12:21:13.451 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: ApplicationUpdate 12:21:13.452 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: AddNodeToNetwork 12:21:13.453 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: RemoveNodeFromNetwork 12:21:13.454 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: CreateNewPrimary 12:21:13.455 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: ControllerChange 12:21:13.456 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: SetLearnMode 12:21:13.458 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: AssignSucReturnRoute 12:21:13.459 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: RequestNetworkUpdate 12:21:13.460 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: SetSucNodeID 12:21:13.461 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: DeleteSUCReturnRoute 12:21:13.462 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: GetSucNodeId 12:21:13.463 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: SendSucId 12:21:13.464 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0x5e 12:21:13.465 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: RequestNodeInfo 12:21:13.466 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: RemoveFailedNodeID 12:21:13.467 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: IsFailedNodeID 12:21:13.468 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: ReplaceFailedNode 12:21:13.469 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0x66 12:21:13.471 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0x67 12:21:13.472 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0x78 12:21:13.473 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: GetRoutingInfo 12:21:13.475 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: LockRoute 12:21:13.476 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0x92 12:21:13.477 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0x93 12:21:13.479 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0x98 12:21:13.480 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0xb4 12:21:13.482 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: WatchDogKick 12:21:13.483 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: WatchDogDisable 12:21:13.484 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0xb8 12:21:13.486 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0xb9 12:21:13.487 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: RfPowerLevelSet 12:21:13.488 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: GetLibraryType 12:21:13.489 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: SendTestFrame 12:21:13.491 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ] - Supports: GetProtocolStatus 12:21:13.492 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0xd2 12:21:13.493 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0xd3 12:21:13.495 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0xd4 12:21:13.496 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0xef 12:21:13.498 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0xf2 12:21:13.499 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0xf4 12:21:13.500 [DEBUG] [ApiGetCapabilitiesMessageClass:56 ] - Supports: Unknown Class 0xf5 12:21:13.502 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74 ] - Sent message Message: class = SerialApiGetCapabilities (0x07), type = Request (0x00), payload = , callbackid = 0 12:21:13.508 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ] - Recv message Message: class = SerialApiGetCapabilities (0x07), type = Response (0x01), payload = 05 02 01 15 04 00 00 01 FE 83 FF 88 CF 1F 00 00 FB 9F 7D A0 67 00 80 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 40 1A 00 , callbackid = 0 12:21:13.510 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:88 ] - Checking transaction complete: class=SerialApiGetCapabilities, callback id=0, expected=SerialApiGetCapabilities, cancelled=false transaction complete! 12:21:13.512 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = SerialApiGetCapabilities (0x07), type = Request (0x00), payload = , callbackid = 0, state=true] 12:21:13.513 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = SerialApiGetCapabilities (0x07), type = Request (0x00), payload = , callbackid = 0, state=true] 12:21:13.515 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 255: Processing event ourselves 12:21:13.516 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 255: Response processed for callback id 0 after 165ms/165ms. 12:21:13.519 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 255: Creating empty message of class = SerialApiGetInitData (0x02), type = Request (0x00) 12:21:13.520 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 3 12:21:13.521 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 2 12:21:13.523 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 05 00 06 96 0F 65 12:21:13.525 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 255: Sending REQUEST Message = Message: class = SerialApiSetTimeouts (0x06), type = Request (0x00), payload = 96 0F , callbackid = 0 12:21:13.529 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 05 01 06 96 0F 64 12:21:13.533 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:13.533 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:13.535 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 05 01 06 96 0F 64 12:21:13.538 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 05 01 06 96 0F 64 12:21:13.540 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = SerialApiSetTimeouts (0x06), type = Response (0x01), payload = 96 0F , callbackid = 0 12:21:13.541 [DEBUG] [rialApiSetTimeoutsMessageClass:40 ] - Got SerialApiSetTimeouts response. ACK=150, BYTE=15 12:21:13.543 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74 ] - Sent message Message: class = SerialApiSetTimeouts (0x06), type = Request (0x00), payload = 96 0F , callbackid = 0 12:21:13.545 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ] - Recv message Message: class = SerialApiSetTimeouts (0x06), type = Response (0x01), payload = 96 0F , callbackid = 0 12:21:13.546 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:88 ] - Checking transaction complete: class=SerialApiSetTimeouts, callback id=0, expected=SerialApiSetTimeouts, cancelled=false transaction complete! 12:21:13.548 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = SerialApiSetTimeouts (0x06), type = Request (0x00), payload = 96 0F , callbackid = 0, state=true] 12:21:13.551 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = SerialApiSetTimeouts (0x06), type = Request (0x00), payload = 96 0F , callbackid = 0, state=true] 12:21:13.552 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 255: Processing event ourselves 12:21:13.553 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 255: Response processed for callback id 0 after 27ms/165ms. 12:21:13.555 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 1 12:21:13.557 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 03 00 56 AA 12:21:13.558 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 255: Sending REQUEST Message = Message: class = GetSucNodeId (0x56), type = Request (0x00), payload = , callbackid = 0 12:21:13.561 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 04 01 56 00 AC 12:21:13.564 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:13.564 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:13.567 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 04 01 56 00 AC 12:21:13.568 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 04 01 56 00 AC 12:21:13.569 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = GetSucNodeId (0x56), type = Response (0x01), payload = 00 , callbackid = 0 12:21:13.570 [DEBUG] [i.p.s.GetSucNodeIdMessageClass:41 ] - Got SUC NodeID response. 12:21:13.571 [DEBUG] [i.p.s.GetSucNodeIdMessageClass:47 ] - No SUC Node is set 12:21:13.573 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74 ] - Sent message Message: class = GetSucNodeId (0x56), type = Request (0x00), payload = , callbackid = 0 12:21:13.574 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ] - Recv message Message: class = GetSucNodeId (0x56), type = Response (0x01), payload = 00 , callbackid = 0 12:21:13.575 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:88 ] - Checking transaction complete: class=GetSucNodeId, callback id=0, expected=GetSucNodeId, cancelled=false transaction complete! 12:21:13.576 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = GetSucNodeId (0x56), type = Request (0x00), payload = , callbackid = 0, state=true] 12:21:13.578 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = GetSucNodeId (0x56), type = Request (0x00), payload = , callbackid = 0, state=true] 12:21:13.579 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 255: Processing event ourselves 12:21:13.580 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 255: Response processed for callback id 0 after 21ms/165ms. 12:21:13.581 [DEBUG] [rollerCapabilitiesMessageClass:41 ] - Creating GET_CONTROLLER_CAPABILITIES message 12:21:13.582 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 255: Creating empty message of class = GetControllerCapabilities (0x05), type = Request (0x00) 12:21:13.584 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 2 12:21:13.585 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 1 12:21:13.586 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 03 00 02 FE 12:21:13.588 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 255: Sending REQUEST Message = Message: class = SerialApiGetInitData (0x02), type = Request (0x00), payload = , callbackid = 0 12:21:13.652 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 25 01 02 05 00 1D 11 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 05 00 D1 12:21:13.660 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:13.660 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:13.664 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 25 01 02 05 00 1D 11 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 05 00 D1 12:21:13.667 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 25 01 02 05 00 1D 11 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 05 00 D1 12:21:13.671 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = SerialApiGetInitData (0x02), type = Response (0x01), payload = 05 00 1D 11 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 05 00 , callbackid = 0 12:21:13.672 [DEBUG] [rialApiGetInitDataMessageClass:39 ] - Got MessageSerialApiGetInitData response.

Thanks,
Shrikant

12:21:13.672 [DEBUG] [rialApiGetInitDataMessageClass:39 ] - Got MessageSerialApiGetInitData response. 12:21:13.673 [INFO ] [rialApiGetInitDataMessageClass:57 ] - NODE 1: Node found 12:21:13.674 [INFO ] [rialApiGetInitDataMessageClass:57 ] - NODE 5: Node found 12:21:13.675 [INFO ] [rialApiGetInitDataMessageClass:57 ] - NODE 11: Node found 12:21:13.677 [INFO ] [rialApiGetInitDataMessageClass:65 ] - ZWave Controller using Controller API 12:21:13.678 [INFO ] [rialApiGetInitDataMessageClass:66 ] - ZWave Controller is Primary Controller 12:21:13.679 [INFO ] [rialApiGetInitDataMessageClass:67 ] - ------------Number of Nodes Found Registered to ZWave Controller------------ 12:21:13.680 [INFO ] [rialApiGetInitDataMessageClass:68 ] - # Nodes = 3 12:21:13.681 [INFO ] [rialApiGetInitDataMessageClass:69 ] - ---------------------------------------------------------------------------- 12:21:13.682 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74 ] - Sent message Message: class = SerialApiGetInitData (0x02), type = Request (0x00), payload = , callbackid = 0 12:21:13.686 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ] - Recv message Message: class = SerialApiGetInitData (0x02), type = Response (0x01), payload = 05 00 1D 11 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 05 00 , callbackid = 0 12:21:13.688 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:88 ] - Checking transaction complete: class=SerialApiGetInitData, callback id=0, expected=SerialApiGetInitData, cancelled=false transaction complete! 12:21:13.689 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = SerialApiGetInitData (0x02), type = Request (0x00), payload = , callbackid = 0, state=true] 12:21:13.691 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = SerialApiGetInitData (0x02), type = Request (0x00), payload = , callbackid = 0, state=true] 12:21:13.692 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 255: Processing event ourselves 12:21:13.693 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 255: Response processed for callback id 0 after 105ms/165ms. 12:21:13.698 [DEBUG] [b.z.i.protocol.ZWaveController:461 ] - NODE 1: Init node thread start 12:21:13.699 [DEBUG] [b.z.i.protocol.ZWaveController:461 ] - NODE 11: Init node thread start 12:21:13.699 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 0 12:21:13.698 [DEBUG] [b.z.i.protocol.ZWaveController:461 ] - NODE 5: Init node thread start 12:21:13.702 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 03 00 05 F9 12:21:13.705 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 255: Sending REQUEST Message = Message: class = GetControllerCapabilities (0x05), type = Request (0x00), payload = , callbackid = 0 12:21:13.709 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 04 01 05 08 F7 12:21:13.712 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:13.712 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:13.714 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 04 01 05 08 F7 12:21:13.718 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 04 01 05 08 F7 12:21:13.720 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = GetControllerCapabilities (0x05), type = Response (0x01), payload = 08 , callbackid = 0 12:21:13.722 [DEBUG] [rollerCapabilitiesMessageClass:55 ] - Controller is secondary = false 12:21:13.723 [DEBUG] [rollerCapabilitiesMessageClass:56 ] - Controller is on other network = false 12:21:13.724 [DEBUG] [rollerCapabilitiesMessageClass:57 ] - Node ID Server is present = false 12:21:13.725 [DEBUG] [rollerCapabilitiesMessageClass:58 ] - Controller is real primary = true 12:21:13.726 [DEBUG] [rollerCapabilitiesMessageClass:59 ] - Controller is SUC = false 12:21:13.728 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74 ] - Sent message Message: class = GetControllerCapabilities (0x05), type = Request (0x00), payload = , callbackid = 0 12:21:13.729 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ] - Recv message Message: class = GetControllerCapabilities (0x05), type = Response (0x01), payload = 08 , callbackid = 0 12:21:13.731 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:88 ] - Checking transaction complete: class=GetControllerCapabilities, callback id=0, expected=GetControllerCapabilities, cancelled=false transaction complete! 12:21:13.732 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = GetControllerCapabilities (0x05), type = Request (0x00), payload = , callbackid = 0, state=true] 12:21:13.734 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = GetControllerCapabilities (0x05), type = Request (0x00), payload = , callbackid = 0, state=true] 12:21:13.735 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 255: Processing event ourselves 12:21:13.737 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 255: Response processed for callback id 0 after 31ms/165ms. 12:21:14.588 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:138 ] - NODE 5: Serializing from file etc/zwave/node5.xml 12:21:14.588 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:138 ] - NODE 11: Serializing from file etc/zwave/node11.xml 12:21:14.588 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:138 ] - NODE 1: Serializing from file etc/zwave/node1.xml 12:21:14.701 [DEBUG] [b.z.i.protocol.ZWaveController:497 ] - NODE 1: Restore from config: Ok. 12:21:14.760 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:276 ] - NODE 1: Node advancer - EMPTYNODE: queue length(0), free to send(true) 12:21:14.763 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1143 ] - NODE 1: Initialisation retry timer started 5000 12:21:14.764 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 1: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false) 12:21:14.766 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:347 ] - NODE 1: Node advancer: Initialisation starting 12:21:14.768 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:905 ] - NODE 1: Node advancer - advancing to PROTOINFO 12:21:14.769 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 1: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true) 12:21:14.770 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:356 ] - NODE 1: Node advancer: PROTOINFO - send IdentifyNode 12:21:14.774 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 255: Creating empty message of class = IdentifyNode (0x41), type = Request (0x00) 12:21:14.776 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 1 12:21:14.776 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 0 12:21:14.777 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:249 ] - NODE 1: Node advancer - queued packet. Queue length is 1 12:21:14.778 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 04 00 41 01 BB 12:21:14.778 [DEBUG] [b.z.i.protocol.ZWaveController:553 ] - NODE 1: Init node thread finished 12:21:14.781 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 255: Sending REQUEST Message = Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 01 , callbackid = 0 12:21:14.788 [DEBUG] [b.z.i.protocol.ZWaveController:497 ] - NODE 11: Restore from config: Ok. 12:21:14.790 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:276 ] - NODE 11: Node advancer - EMPTYNODE: queue length(0), free to send(true) 12:21:14.791 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1143 ] - NODE 11: Initialisation retry timer started 5000 12:21:14.792 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 11: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false) 12:21:14.794 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:347 ] - NODE 11: Node advancer: Initialisation starting 12:21:14.795 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:905 ] - NODE 11: Node advancer - advancing to PROTOINFO 12:21:14.796 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 11: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true) 12:21:14.798 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:356 ] - NODE 11: Node advancer: PROTOINFO - send IdentifyNode 12:21:14.800 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 255: Creating empty message of class = IdentifyNode (0x41), type = Request (0x00) 12:21:14.801 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 1 12:21:14.803 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:249 ] - NODE 11: Node advancer - queued packet. Queue length is 1 12:21:14.804 [DEBUG] [b.z.i.protocol.ZWaveController:553 ] - NODE 11: Init node thread finished 12:21:14.836 [DEBUG] [b.z.i.protocol.ZWaveController:497 ] - NODE 5: Restore from config: Ok. 12:21:14.839 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:276 ] - NODE 5: Node advancer - EMPTYNODE: queue length(0), free to send(true) 12:21:14.840 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 5: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false) 12:21:14.842 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:347 ] - NODE 5: Node advancer: Initialisation starting 12:21:14.843 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:905 ] - NODE 5: Node advancer - advancing to PROTOINFO 12:21:14.844 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 5: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true) 12:21:14.846 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:356 ] - NODE 5: Node advancer: PROTOINFO - send IdentifyNode 12:21:14.848 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 255: Creating empty message of class = IdentifyNode (0x41), type = Request (0x00) 12:21:14.849 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 2 12:21:14.850 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:249 ] - NODE 5: Node advancer - queued packet. Queue length is 1 12:21:14.852 [DEBUG] [b.z.i.protocol.ZWaveController:553 ] - NODE 5: Init node thread finished 12:21:14.925 [DEBUG] [z.internal.ZWaveNetworkMonitor:315 ] - Network Monitor: Queue length is 2 - deferring network monitor functions. 12:21:15.765 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 09 01 41 93 16 01 02 02 01 33 12:21:15.768 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:15.768 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:15.771 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 09 01 41 93 16 01 02 02 01 33 12:21:15.773 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 09 01 41 93 16 01 02 02 01 33 12:21:15.775 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = IdentifyNode (0x41), type = Response (0x01), payload = 93 16 01 02 02 01 , callbackid = 0 12:21:15.776 [DEBUG] [i.p.s.IdentifyNodeMessageClass:52 ] - NODE 1: ProtocolInfo 12:21:15.778 [DEBUG] [i.p.s.IdentifyNodeMessageClass:61 ] - NODE 1: Listening = true 12:21:15.779 [DEBUG] [i.p.s.IdentifyNodeMessageClass:62 ] - NODE 1: Routing = false 12:21:15.780 [DEBUG] [i.p.s.IdentifyNodeMessageClass:63 ] - NODE 1: Version = 4 12:21:15.781 [DEBUG] [i.p.s.IdentifyNodeMessageClass:64 ] - NODE 1: FLIRS = false 12:21:15.783 [DEBUG] [i.p.s.IdentifyNodeMessageClass:76 ] - NODE 1: Basic = Static Controller 12:21:15.785 [DEBUG] [i.p.s.IdentifyNodeMessageClass:83 ] - NODE 1: Generic = Static Controller 12:21:15.786 [DEBUG] [i.p.s.IdentifyNodeMessageClass:90 ] - NODE 1: Specific = PC Controller 12:21:15.788 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:222 ] - NODE 1: Creating new instance of command class NO_OPERATION 12:21:15.790 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:222 ] - NODE 1: Creating new instance of command class BASIC 12:21:15.792 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74 ] - Sent message Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 01 , callbackid = 0 12:21:15.794 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ] - Recv message Message: class = IdentifyNode (0x41), type = Response (0x01), payload = 93 16 01 02 02 01 , callbackid = 0 12:21:15.795 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:88 ] - Checking transaction complete: class=IdentifyNode, callback id=0, expected=IdentifyNode, cancelled=false transaction complete! 12:21:15.798 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 01 , callbackid = 0, state=true] 12:21:15.799 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 01 , callbackid = 0, state=true] 12:21:15.801 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1050 ] - NODE 1: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true) 12:21:15.803 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ] - NODE 1: Node advancer - checking initialisation queue. Queue size 1. 12:21:15.804 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:213 ] - NODE 1: Node advancer - message removed from queue. Queue size 0. 12:21:15.806 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:276 ] - NODE 1: Node advancer - PROTOINFO: queue length(0), free to send(true) 12:21:15.808 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1143 ] - NODE 1: Initialisation retry timer started 5000 12:21:15.809 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 1: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false) 12:21:15.810 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:905 ] - NODE 1: Node advancer - advancing to NEIGHBORS 12:21:15.811 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 1: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true) 12:21:15.813 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:366 ] - NODE 1: Node advancer: NEIGHBORS - send RoutingInfo 12:21:15.815 [DEBUG] [p.s.GetRoutingInfoMessageClass:29 ] - NODE 1: Request routing info 12:21:15.817 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 255: Creating empty message of class = GetRoutingInfo (0x80), type = Request (0x00) 12:21:15.818 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 3 12:21:15.820 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:249 ] - NODE 1: Node advancer - queued packet. Queue length is 1 12:21:15.821 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 255: Processing event ourselves 12:21:15.822 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 255: Response processed for callback id 0 after 1040ms/1040ms. 12:21:15.823 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 2 12:21:15.825 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 04 00 41 0B B1 12:21:15.826 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 255: Sending REQUEST Message = Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 0B , callbackid = 0 12:21:15.831 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 09 01 41 53 DC 00 04 40 03 7E 12:21:15.834 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:15.834 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:15.836 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 09 01 41 53 DC 00 04 40 03 7E 12:21:15.838 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 09 01 41 53 DC 00 04 40 03 7E 12:21:15.840 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = IdentifyNode (0x41), type = Response (0x01), payload = 53 DC 00 04 40 03 , callbackid = 0 12:21:15.841 [DEBUG] [i.p.s.IdentifyNodeMessageClass:52 ] - NODE 11: ProtocolInfo 12:21:15.842 [DEBUG] [i.p.s.IdentifyNodeMessageClass:61 ] - NODE 11: Listening = false 12:21:15.844 [DEBUG] [i.p.s.IdentifyNodeMessageClass:62 ] - NODE 11: Routing = true 12:21:15.845 [DEBUG] [i.p.s.IdentifyNodeMessageClass:63 ] - NODE 11: Version = 4 12:21:15.846 [DEBUG] [i.p.s.IdentifyNodeMessageClass:64 ] - NODE 11: FLIRS = true 12:21:15.847 [DEBUG] [i.p.s.IdentifyNodeMessageClass:76 ] - NODE 11: Basic = Routing Slave 12:21:15.848 [DEBUG] [i.p.s.IdentifyNodeMessageClass:83 ] - NODE 11: Generic = Entry Control 12:21:15.849 [DEBUG] [i.p.s.IdentifyNodeMessageClass:90 ] - NODE 11: Specific = Secure Keypad Door Lock 12:21:15.851 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:222 ] - NODE 11: Creating new instance of command class NO_OPERATION 12:21:15.852 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:222 ] - NODE 11: Creating new instance of command class BASIC 12:21:15.853 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:222 ] - NODE 11: Creating new instance of command class LOCK

12:21:15.856 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74 ] - Sent message Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 0B , callbackid = 0 12:21:15.858 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ] - Recv message Message: class = IdentifyNode (0x41), type = Response (0x01), payload = 53 DC 00 04 40 03 , callbackid = 0 12:21:15.859 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:88 ] - Checking transaction complete: class=IdentifyNode, callback id=0, expected=IdentifyNode, cancelled=false transaction complete! 12:21:15.861 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 0B , callbackid = 0, state=true] 12:21:15.863 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 0B , callbackid = 0, state=true] 12:21:15.864 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1050 ] - NODE 11: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true) 12:21:15.865 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ] - NODE 11: Node advancer - checking initialisation queue. Queue size 1. 12:21:15.867 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:213 ] - NODE 11: Node advancer - message removed from queue. Queue size 0. 12:21:15.868 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:276 ] - NODE 11: Node advancer - PROTOINFO: queue length(0), free to send(true) 12:21:15.870 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1143 ] - NODE 11: Initialisation retry timer started 5000 12:21:15.871 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 11: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false) 12:21:15.873 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:905 ] - NODE 11: Node advancer - advancing to NEIGHBORS 12:21:15.874 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 11: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true) 12:21:15.875 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:366 ] - NODE 11: Node advancer: NEIGHBORS - send RoutingInfo 12:21:15.876 [DEBUG] [p.s.GetRoutingInfoMessageClass:29 ] - NODE 11: Request routing info 12:21:15.878 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 255: Creating empty message of class = GetRoutingInfo (0x80), type = Request (0x00) 12:21:15.879 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 3 12:21:15.880 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:249 ] - NODE 11: Node advancer - queued packet. Queue length is 1 12:21:15.882 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 255: Processing event ourselves 12:21:15.883 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 255: Response processed for callback id 0 after 55ms/1040ms. 12:21:15.884 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 2 12:21:15.886 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 04 00 41 05 BF 12:21:15.888 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 255: Sending REQUEST Message = Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 05 , callbackid = 0 12:21:15.892 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 09 01 41 53 9C 00 04 20 01 5C 12:21:15.895 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:15.895 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:15.897 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 09 01 41 53 9C 00 04 20 01 5C 12:21:15.899 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 09 01 41 53 9C 00 04 20 01 5C 12:21:15.901 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = IdentifyNode (0x41), type = Response (0x01), payload = 53 9C 00 04 20 01 , callbackid = 0 12:21:15.902 [DEBUG] [i.p.s.IdentifyNodeMessageClass:52 ] - NODE 5: ProtocolInfo 12:21:15.903 [DEBUG] [i.p.s.IdentifyNodeMessageClass:61 ] - NODE 5: Listening = false 12:21:15.904 [DEBUG] [i.p.s.IdentifyNodeMessageClass:62 ] - NODE 5: Routing = true 12:21:15.905 [DEBUG] [i.p.s.IdentifyNodeMessageClass:63 ] - NODE 5: Version = 4 12:21:15.906 [DEBUG] [i.p.s.IdentifyNodeMessageClass:64 ] - NODE 5: FLIRS = false 12:21:15.908 [DEBUG] [i.p.s.IdentifyNodeMessageClass:76 ] - NODE 5: Basic = Routing Slave 12:21:15.908 [DEBUG] [i.p.s.IdentifyNodeMessageClass:83 ] - NODE 5: Generic = Binary Sensor 12:21:15.909 [DEBUG] [i.p.s.IdentifyNodeMessageClass:90 ] - NODE 5: Specific = Routing Binary Sensor 12:21:15.910 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:222 ] - NODE 5: Creating new instance of command class NO_OPERATION 12:21:15.911 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:222 ] - NODE 5: Creating new instance of command class BASIC 12:21:15.912 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:222 ] - NODE 5: Creating new instance of command class SENSOR_BINARY 12:21:15.914 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74 ] - Sent message Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 05 , callbackid = 0 12:21:15.915 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ] - Recv message Message: class = IdentifyNode (0x41), type = Response (0x01), payload = 53 9C 00 04 20 01 , callbackid = 0 12:21:15.916 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:88 ] - Checking transaction complete: class=IdentifyNode, callback id=0, expected=IdentifyNode, cancelled=false transaction complete! 12:21:15.918 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 05 , callbackid = 0, state=true] 12:21:15.919 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 05 , callbackid = 0, state=true] 12:21:15.920 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1050 ] - NODE 5: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true) 12:21:15.921 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ] - NODE 5: Node advancer - checking initialisation queue. Queue size 1. 12:21:15.922 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:213 ] - NODE 5: Node advancer - message removed from queue. Queue size 0. 12:21:15.923 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:276 ] - NODE 5: Node advancer - PROTOINFO: queue length(0), free to send(true) 12:21:15.925 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 5: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false) 12:21:15.926 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:905 ] - NODE 5: Node advancer - advancing to NEIGHBORS 12:21:15.927 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 5: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true) 12:21:15.928 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:366 ] - NODE 5: Node advancer: NEIGHBORS - send RoutingInfo 12:21:15.929 [DEBUG] [p.s.GetRoutingInfoMessageClass:29 ] - NODE 5: Request routing info 12:21:15.930 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 255: Creating empty message of class = GetRoutingInfo (0x80), type = Request (0x00) 12:21:15.932 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 3 12:21:15.933 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:249 ] - NODE 5: Node advancer - queued packet. Queue length is 1 12:21:15.934 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 255: Processing event ourselves 12:21:15.935 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 255: Response processed for callback id 0 after 46ms/1040ms. 12:21:15.936 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 2 12:21:15.938 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 07 00 80 01 00 00 03 7A 12:21:15.940 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 255: Sending REQUEST Message = Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 01 00 00 03 , callbackid = 0 12:21:15.948 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 20 01 80 10 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 4A 12:21:15.953 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:15.953 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:15.956 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 20 01 80 10 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 4A 12:21:15.959 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 20 01 80 10 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 4A 12:21:15.961 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = GetRoutingInfo (0x80), type = Response (0x01), payload = 10 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 , callbackid = 0 12:21:15.963 [DEBUG] [p.s.GetRoutingInfoMessageClass:47 ] - NODE 1: Got NodeRoutingInfo request. 12:21:15.964 [DEBUG] [p.s.GetRoutingInfoMessageClass:78 ] - NODE 1: Neighbor nodes: 5 11 12:21:15.971 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 1: Notifying event listeners: ZWaveNetworkEvent: org.openhab.binding.zwave.internal.protocol.event.ZWaveNetworkEvent@371d03 12:21:15.972 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent org.openhab.binding.zwave.internal.protocol.event.ZWaveNetworkEvent@371d03 12:21:15.974 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 1: Processing event ourselves 12:21:15.976 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74 ] - Sent message Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 01 00 00 03 , callbackid = 0 12:21:15.979 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ] - Recv message Message: class = GetRoutingInfo (0x80), type = Response (0x01), payload = 10 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 , callbackid = 0 12:21:15.981 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:88 ] - Checking transaction complete: class=GetRoutingInfo, callback id=0, expected=GetRoutingInfo, cancelled=false transaction complete! 12:21:15.983 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 01 00 00 03 , callbackid = 0, state=true] 12:21:15.985 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 01 00 00 03 , callbackid = 0, state=true] 12:21:15.986 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1050 ] - NODE 1: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true) 12:21:15.987 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ] - NODE 1: Node advancer - checking initialisation queue. Queue size 1. 12:21:15.988 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:213 ] - NODE 1: Node advancer - message removed from queue. Queue size 0. 12:21:15.990 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:276 ] - NODE 1: Node advancer - NEIGHBORS: queue length(0), free to send(true) 12:21:15.991 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1143 ] - NODE 1: Initialisation retry timer started 5000 12:21:15.992 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 1: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false) 12:21:15.994 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:905 ] - NODE 1: Node advancer - advancing to FAILED_CHECK 12:21:15.995 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 1: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true) 12:21:15.996 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:375 ] - NODE 1: Node advancer: FAILED_CHECK - Controller - terminating initialisation 12:21:15.998 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 1: Node advancer: loop - DONE try 0: stageAdvanced(true) 12:21:15.999 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:107 ] - NODE 1: Serializing to file etc/zwave/node1.xml 12:21:16.056 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:864 ] - NODE 1: Node advancer: Initialisation complete! 12:21:16.058 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 1: Notifying event listeners: ZWaveInitializationCompletedEvent: org.openhab.binding.zwave.internal.protocol.event.ZWaveInitializationCompletedEvent@1226d97 12:21:16.059 [DEBUG] [.z.internal.ZWaveActiveBinding:435 ] - NODE 1: ZWaveIncomingEvent Called, Network Event, Init Done. Setting device ready. 12:21:16.061 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ] - NODE 11: Polling list: item USER_CODE_233_234_6_1 is not completed initialisation 12:21:16.062 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ] - NODE 11: Polling list: item DOOR_LOCK_233_234_6_1 is not completed initialisation 12:21:16.063 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ] - NODE 11: Polling list: item BATTERY_233_234_6_1 is not completed initialisation 12:21:16.064 [DEBUG] [.z.internal.ZWaveActiveBinding:193 ] - NODE 5: Polling list: item SENSOR_DOOR_233_234_5_1 is not completed initialisation 12:21:16.065 [DEBUG] [z.internal.ZWaveNetworkMonitor:730 ] - Network initialised - starting network monitor. 12:21:16.066 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 1: Processing event ourselves 12:21:16.067 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 255: Processing event ourselves 12:21:16.068 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 255: Response processed for callback id 0 after 127ms/1040ms. 12:21:16.070 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 1 12:21:16.071 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 07 00 80 0B 00 00 03 70 12:21:16.073 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 255: Sending REQUEST Message = Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 0B 00 00 03 , callbackid = 0 12:21:16.079 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 20 01 80 01 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 5F 12:21:16.083 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:16.084 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=0 12:21:16.086 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 20 01 80 01 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 5F 12:21:16.089 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 20 01 80 01 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 5F 12:21:16.091 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = GetRoutingInfo (0x80), type = Response (0x01), payload = 01 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 , callbackid = 0 12:21:16.092 [DEBUG] [p.s.GetRoutingInfoMessageClass:47 ] - NODE 11: Got NodeRoutingInfo request. 12:21:16.093 [DEBUG] [p.s.GetRoutingInfoMessageClass:78 ] - NODE 11: Neighbor nodes: 1 12:21:16.095 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 11: Notifying event listeners: ZWaveNetworkEvent: org.openhab.binding.zwave.internal.protocol.event.ZWaveNetworkEvent@12d8a4 12:21:16.096 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent org.openhab.binding.zwave.internal.protocol.event.ZWaveNetworkEvent@12d8a4 12:21:16.097 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 11: Processing event ourselves 12:21:16.098 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74 ] - Sent message Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 0B 00 00 03 , callbackid = 0 12:21:16.100 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ] - Recv message Message: class = GetRoutingInfo (0x80), type = Response (0x01), payload = 01 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 , callbackid = 0 12:21:16.101 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:88 ] - Checking transaction complete: class=GetRoutingInfo, callback id=0, expected=GetRoutingInfo, cancelled=false transaction complete! 12:21:16.103 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 0B 00 00 03 , callbackid = 0, state=true] 12:21:16.105 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 0B 00 00 03 , callbackid = 0, state=true] 12:21:16.106 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1050 ] - NODE 11: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true) 12:21:16.107 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ] - NODE 11: Node advancer - checking initialisation queue. Queue size 1. 12:21:16.108 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:213 ] - NODE 11: Node advancer - message removed from queue. Queue size 0. 12:21:16.109 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:276 ] - NODE 11: Node advancer - NEIGHBORS: queue length(0), free to send(true) 12:21:16.110 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1143 ] - NODE 11: Initialisation retry timer started 5000 12:21:16.111 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 11: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false) 12:21:16.112 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:905 ] - NODE 11: Node advancer - advancing to FAILED_CHECK 12:21:16.114 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 11: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true) 12:21:16.116 [DEBUG] [i.p.s.IsFailedNodeMessageClass:31 ] - NODE 11: Requesting IsFailedNode status from controller. 12:21:16.117 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 255: Creating empty message of class = IsFailedNodeID (0x62), type = Request (0x00) 12:21:16.119 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 2 12:21:16.120 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:249 ] - NODE 11: Node advancer - queued packet. Queue length is 1 12:21:16.121 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 255: Processing event ourselves 12:21:16.122 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 255: Response processed for callback id 0 after 49ms/1040ms. 12:21:16.123 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 1 12:21:16.125 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 07 00 80 05 00 00 03 7E 12:21:16.126 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 255: Sending REQUEST Message = Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 05 00 00 03 , callbackid = 0 12:21:16.132 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 20 01 80 01 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 5F 12:21:16.134 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:16.134 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:16.137 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 20 01 80 01 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 5F 12:21:16.138 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 20 01 80 01 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 5F 12:21:16.140 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = GetRoutingInfo (0x80), type = Response (0x01), payload = 01 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 , callbackid = 0 12:21:16.141 [DEBUG] [p.s.GetRoutingInfoMessageClass:47 ] - NODE 5: Got NodeRoutingInfo request. 12:21:16.143 [DEBUG] [p.s.GetRoutingInfoMessageClass:78 ] - NODE 5: Neighbor nodes: 1 12:21:16.144 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 5: Notifying event listeners: ZWaveNetworkEvent: org.openhab.binding.zwave.internal.protocol.event.ZWaveNetworkEvent@76634c 12:21:16.145 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent org.openhab.binding.zwave.internal.protocol.event.ZWaveNetworkEvent@76634c 12:21:16.146 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 5: Processing event ourselves 12:21:16.147 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74 ] - Sent message Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 05 00 00 03 , callbackid = 0 12:21:16.149 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ] - Recv message Message: class = GetRoutingInfo (0x80), type = Response (0x01), payload = 01 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 , callbackid = 0 12:21:16.150 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:88 ] - Checking transaction complete: class=GetRoutingInfo, callback id=0, expected=GetRoutingInfo, cancelled=false transaction complete! 12:21:16.152 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 05 00 00 03 , callbackid = 0, state=true] 12:21:16.153 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 05 00 00 03 , callbackid = 0, state=true] 12:21:16.155 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1050 ] - NODE 5: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true) 12:21:16.156 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ] - NODE 5: Node advancer - checking initialisation queue. Queue size 1. 12:21:16.157 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:213 ] - NODE 5: Node advancer - message removed from queue. Queue size 0. 12:21:16.158 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:276 ] - NODE 5: Node advancer - NEIGHBORS: queue length(0), free to send(true) 12:21:16.159 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 5: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false) 12:21:16.161 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:905 ] - NODE 5: Node advancer - advancing to FAILED_CHECK 12:21:16.162 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 5: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true) 12:21:16.163 [DEBUG] [i.p.s.IsFailedNodeMessageClass:31 ] - NODE 5: Requesting IsFailedNode status from controller. 12:21:16.164 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 255: Creating empty message of class = IsFailedNodeID (0x62), type = Request (0x00) 12:21:16.166 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 2 12:21:16.167 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:249 ] - NODE 5: Node advancer - queued packet. Queue length is 1 12:21:16.168 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 255: Processing event ourselves 12:21:16.169 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 255: Response processed for callback id 0 after 43ms/1040ms. 12:21:16.170 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 1 12:21:16.171 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 04 00 62 0B 92 12:21:16.172 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 255: Sending REQUEST Message = Message: class = IsFailedNodeID (0x62), type = Request (0x00), payload = 0B , callbackid = 0 12:21:16.175 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 04 01 62 01 99 12:21:16.177 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:16.177 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:16.178 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 04 01 62 01 99 12:21:16.181 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 04 01 62 01 99 12:21:16.182 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = IsFailedNodeID (0x62), type = Response (0x01), payload = 01 , callbackid = 0 12:21:16.184 [WARN ] [i.p.s.IsFailedNodeMessageClass:50 ] - NODE 11: Is currently marked as failed by the controller! 12:21:16.185 [DEBUG] [.z.internal.protocol.ZWaveNode:243 ] - NODE 11: Node is DEAD. 12:21:16.186 [DEBUG] [.z.internal.protocol.ZWaveNode:253 ] - NODE 11: Initialisation incomplete, not signalling state change. 12:21:16.188 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74 ] - Sent message Message: class = IsFailedNodeID (0x62), type = Request (0x00), payload = 0B , callbackid = 0

12:21:16.189 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ] - Recv message Message: class = IsFailedNodeID (0x62), type = Response (0x01), payload = 01 , callbackid = 0 12:21:16.190 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:88 ] - Checking transaction complete: class=IsFailedNodeID, callback id=0, expected=IsFailedNodeID, cancelled=false transaction complete! 12:21:16.191 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = IsFailedNodeID (0x62), type = Request (0x00), payload = 0B , callbackid = 0, state=true] 12:21:16.193 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = IsFailedNodeID (0x62), type = Request (0x00), payload = 0B , callbackid = 0, state=true] 12:21:16.194 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1050 ] - NODE 11: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true) 12:21:16.195 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ] - NODE 11: Node advancer - checking initialisation queue. Queue size 1. 12:21:16.196 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:213 ] - NODE 11: Node advancer - message removed from queue. Queue size 0. 12:21:16.197 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:276 ] - NODE 11: Node advancer - FAILED_CHECK: queue length(0), free to send(true) 12:21:16.198 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1143 ] - NODE 11: Initialisation retry timer started 5000 12:21:16.199 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 11: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false) 12:21:16.201 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:905 ] - NODE 11: Node advancer - advancing to WAIT 12:21:16.202 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 11: Node advancer: loop - WAIT try 0: stageAdvanced(true) 12:21:16.203 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:389 ] - NODE 11: Node advancer: WAIT - Listening=false, FrequentlyListening=true 12:21:16.204 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:393 ] - NODE 11: Node advancer: WAIT - Advancing 12:21:16.206 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:905 ] - NODE 11: Node advancer - advancing to PING 12:21:16.207 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 11: Node advancer: loop - PING try 0: stageAdvanced(true) 12:21:16.208 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:426 ] - NODE 11: Node advancer: PING - send NoOperation 12:21:16.209 [DEBUG] [c.ZWaveNoOperationCommandClass:72 ] - NODE 11: Creating new message for command No Operation 12:21:16.211 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 11: Creating empty message of class = SendData (0x13), type = Request (0x00) 12:21:16.212 [DEBUG] [b.z.i.protocol.ZWaveController:929 ] - Callback ID = 2 12:21:16.214 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 2 12:21:16.215 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:249 ] - NODE 11: Node advancer - queued packet. Queue length is 1 12:21:16.216 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 255: Processing event ourselves 12:21:16.218 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 255: Response processed for callback id 0 after 45ms/1040ms. 12:21:16.219 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 1 12:21:16.222 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 04 00 62 05 9C 12:21:16.223 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 255: Sending REQUEST Message = Message: class = IsFailedNodeID (0x62), type = Request (0x00), payload = 05 , callbackid = 0 12:21:16.226 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 04 01 62 00 98 12:21:16.228 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:16.228 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:16.230 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 04 01 62 00 98 12:21:16.231 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 04 01 62 00 98 12:21:16.232 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = IsFailedNodeID (0x62), type = Response (0x01), payload = 00 , callbackid = 0 12:21:16.233 [DEBUG] [i.p.s.IsFailedNodeMessageClass:54 ] - NODE 5: Is currently marked as healthy by the controller 12:21:16.235 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:74 ] - Sent message Message: class = IsFailedNodeID (0x62), type = Request (0x00), payload = 05 , callbackid = 0 12:21:16.236 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85 ] - Recv message Message: class = IsFailedNodeID (0x62), type = Response (0x01), payload = 00 , callbackid = 0 12:21:16.238 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:88 ] - Checking transaction complete: class=IsFailedNodeID, callback id=0, expected=IsFailedNodeID, cancelled=false transaction complete! 12:21:16.239 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 255: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = IsFailedNodeID (0x62), type = Request (0x00), payload = 05 , callbackid = 0, state=true] 12:21:16.241 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = IsFailedNodeID (0x62), type = Request (0x00), payload = 05 , callbackid = 0, state=true] 12:21:16.242 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1050 ] - NODE 5: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true) 12:21:16.243 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ] - NODE 5: Node advancer - checking initialisation queue. Queue size 1. 12:21:16.244 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:213 ] - NODE 5: Node advancer - message removed from queue. Queue size 0. 12:21:16.245 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:276 ] - NODE 5: Node advancer - FAILED_CHECK: queue length(0), free to send(true) 12:21:16.246 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 5: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false) 12:21:16.247 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:905 ] - NODE 5: Node advancer - advancing to WAIT 12:21:16.248 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 5: Node advancer: loop - WAIT try 0: stageAdvanced(true) 12:21:16.249 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:389 ] - NODE 5: Node advancer: WAIT - Listening=false, FrequentlyListening=false 12:21:16.250 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:407 ] - NODE 5: Node advancer: WAIT - Still waiting! 12:21:16.251 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 255: Processing event ourselves 12:21:16.252 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 255: Response processed for callback id 0 after 28ms/1040ms. 12:21:16.253 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 0 12:21:16.255 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 08 00 13 0B 01 00 25 02 C9 12:21:16.256 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 11: Sending REQUEST Message = Message: class = SendData (0x13), type = Request (0x00), payload = 0B 01 00 , callbackid = 2 12:21:16.264 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 04 01 13 01 E8 12:21:16.265 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:16.265 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:16.268 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 04 01 13 01 E8 12:21:16.269 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 04 01 13 01 E8 12:21:16.270 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = SendData (0x13), type = Response (0x01), payload = 01 , callbackid = 0 12:21:16.273 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39 ] - NODE 11: Sent Data successfully placed on stack. 12:21:19.737 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 07 00 13 02 01 01 5C B5 12:21:20.363 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:20.363 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:20.365 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 09 00 13 02 01 01 5C 00 00 BB 12:21:20.366 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 09 00 13 02 01 01 5C 00 00 BB 12:21:20.368 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = SendData (0x13), type = Request (0x00), payload = 02 01 01 5C , callbackid = 0 12:21:20.372 [DEBUG] [b.z.i.p.s.SendDataMessageClass:75 ] - NODE 11: SendData Request. CallBack ID = 2, Status = Transmission complete, no ACK received(1) 12:21:20.374 [ERROR] [b.z.i.p.s.SendDataMessageClass:142 ] - NODE 11: Node is DEAD. Dropping message. 12:21:20.375 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 11: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = SendData (0x13), type = Request (0x00), payload = 0B 01 00 , callbackid = 2, state=false] 12:21:20.377 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = SendData (0x13), type = Request (0x00), payload = 0B 01 00 , callbackid = 2, state=false] 12:21:20.378 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1050 ] - NODE 11: Node advancer - PING: Transaction complete (SendData:Request) success(false) 12:21:20.379 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1036 ] - NODE 5: Node advancer - WAIT: The WAIT is over! 12:21:20.380 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ] - NODE 5: Node advancer - checking initialisation queue. Queue size 0. 12:21:20.381 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 11: Processing event ourselves 12:21:20.383 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 11: Response processed for callback id 2 after 4126ms/4126ms. 12:21:21.198 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1111 ] - NODE 11: Stage PING. Initialisation retry timer triggered. Increased to 10000 12:21:21.200 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:276 ] - NODE 11: Node advancer - PING: queue length(0), free to send(false) 12:21:21.201 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1143 ] - NODE 11: Initialisation retry timer started 10000 12:21:21.202 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 11: Node advancer: loop - PING try 1: stageAdvanced(false) 12:21:21.204 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:426 ] - NODE 11: Node advancer: PING - send NoOperation 12:21:21.205 [DEBUG] [c.ZWaveNoOperationCommandClass:72 ] - NODE 11: Creating new message for command No Operation 12:21:21.206 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 11: Creating empty message of class = SendData (0x13), type = Request (0x00) 12:21:21.207 [DEBUG] [b.z.i.protocol.ZWaveController:929 ] - Callback ID = 3 12:21:21.209 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 1 12:21:21.209 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 0 12:21:21.210 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:249 ] - NODE 11: Node advancer - queued packet. Queue length is 1 12:21:21.211 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 08 00 13 0B 01 00 25 03 C8 12:21:21.213 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 11: Sending REQUEST Message = Message: class = SendData (0x13), type = Request (0x00), payload = 0B 01 00 , callbackid = 3 12:21:21.222 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 04 01 13 01 E8 12:21:21.223 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:21.223 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:21.225 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 04 01 13 01 E8 12:21:21.227 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 04 01 13 01 E8 12:21:21.228 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = SendData (0x13), type = Response (0x01), payload = 01 , callbackid = 0 12:21:21.230 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39 ] - NODE 11: Sent Data successfully placed on stack. 12:21:24.694 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 07 00 13 03 01 01 5C B4 12:21:25.322 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:25.323 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 09 00 13 03 01 01 5C 00 00 BA 12:21:25.323 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=0 12:21:25.324 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 09 00 13 03 01 01 5C 00 00 BA 12:21:25.328 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = SendData (0x13), type = Request (0x00), payload = 03 01 01 5C , callbackid = 0 12:21:25.329 [DEBUG] [b.z.i.p.s.SendDataMessageClass:75 ] - NODE 11: SendData Request. CallBack ID = 3, Status = Transmission complete, no ACK received(1) 12:21:25.330 [ERROR] [b.z.i.p.s.SendDataMessageClass:142 ] - NODE 11: Node is DEAD. Dropping message. 12:21:25.332 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 11: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = SendData (0x13), type = Request (0x00), payload = 0B 01 00 , callbackid = 3, state=false] 12:21:25.333 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = SendData (0x13), type = Request (0x00), payload = 0B 01 00 , callbackid = 3, state=false] 12:21:25.334 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1050 ] - NODE 11: Node advancer - PING: Transaction complete (SendData:Request) success(false) 12:21:25.336 [DEBUG] [b.z.i.protocol.ZWaveController:627 ] - NODE 11: Processing event ourselves 12:21:25.337 [DEBUG] [WaveController$ZWaveSendThread:1349 ] - NODE 11: Response processed for callback id 3 after 4123ms/4126ms. 12:21:31.201 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1111 ] - NODE 11: Stage PING. Initialisation retry timer triggered. Increased to 20000 12:21:31.204 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:276 ] - NODE 11: Node advancer - PING: queue length(0), free to send(false) 12:21:31.207 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1143 ] - NODE 11: Initialisation retry timer started 20000 12:21:31.209 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ] - NODE 11: Node advancer: loop - PING try 2: stageAdvanced(false) 12:21:31.212 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:426 ] - NODE 11: Node advancer: PING - send NoOperation 12:21:31.214 [DEBUG] [c.ZWaveNoOperationCommandClass:72 ] - NODE 11: Creating new message for command No Operation 12:21:31.217 [DEBUG] [o.b.z.i.protocol.SerialMessage:111 ] - NODE 11: Creating empty message of class = SendData (0x13), type = Request (0x00) 12:21:31.220 [DEBUG] [b.z.i.protocol.ZWaveController:929 ] - Callback ID = 4 12:21:31.222 [DEBUG] [b.z.i.protocol.ZWaveController:600 ] - Enqueueing message. Queue length = 1 12:21:31.222 [DEBUG] [WaveController$ZWaveSendThread:1220 ] - Took message from queue for sending. Queue length = 0 12:21:31.225 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 08 00 13 0B 01 00 25 04 CF 12:21:31.226 [DEBUG] [WaveController$ZWaveSendThread:1277 ] - NODE 11: Sending REQUEST Message = Message: class = SendData (0x13), type = Request (0x00), payload = 0B 01 00 , callbackid = 4 12:21:31.227 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:249 ] - NODE 11: Node advancer - queued packet. Queue length is 1 12:21:31.474 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 04 01 13 01 E8 12:21:31.476 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=1 12:21:31.476 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:31.478 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 04 01 13 01 E8 12:21:31.479 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 04 01 13 01 E8 12:21:31.480 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = SendData (0x13), type = Response (0x01), payload = 01 , callbackid = 0 12:21:31.481 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39 ] - NODE 11: Sent Data successfully placed on stack. 12:21:34.978 [DEBUG] [eController$ZWaveReceiveThread:1507 ] - Receive Message = 01 07 00 13 04 01 01 5F B0 12:21:35.574 [DEBUG] [b.z.i.protocol.ZWaveController:1168 ] - Receive queue TAKE: Length=0 12:21:35.576 [DEBUG] [o.b.z.i.protocol.SerialMessage:239 ] - Assembled message buffer = 01 09 00 13 04 01 01 5F 00 00 BE 12:21:35.576 [DEBUG] [eController$ZWaveReceiveThread:1431 ] - Receive queue ADD: Length=0 12:21:35.577 [DEBUG] [b.z.i.protocol.ZWaveController:1169 ] - Process Message = 01 09 00 13 04 01 01 5F 00 00 BE 12:21:35.579 [DEBUG] [b.z.i.protocol.ZWaveController:196 ] - Message: class = SendData (0x13), type = Request (0x00), payload = 04 01 01 5F , callbackid = 0 12:21:35.581 [DEBUG] [b.z.i.p.s.SendDataMessageClass:75 ] - NODE 11: SendData Request. CallBack ID = 4, Status = Transmission complete, no ACK received(1) 12:21:35.582 [ERROR] [b.z.i.p.s.SendDataMessageClass:142 ] - NODE 11: Node is DEAD. Dropping message. 12:21:35.583 [DEBUG] [b.z.i.protocol.ZWaveController:616 ] - NODE 11: Notifying event listeners: ZWaveTransactionCompletedEvent: ZWaveTransactionCompletedEvent [completedMessage=Message: class = SendData (0x13), type = Request (0x00), payload = 0B 01 00 , callbackid = 4, state=false] 12:21:35.584 [DEBUG] [.z.internal.ZWaveActiveBinding:443 ] - ZwaveIncomingEvent ZWaveTransactionCompletedEvent [completedMessage=Message: class = SendData (0x13), type = Request (0x00), payload = 0B 01 00 , callbackid = 4, state=false] 12:21:35.586 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1050 ] - NODE 11: Node advancer - PING: Transaction complete (SendData:Request) success(false

Hi @chris,
i uploaded all the debug logs, can u please check the problem of continuous dead node 11

Thanks,
shrikant

Sorry - it’s really not a good idea to paste loads of logs into the forum. It’s extremely difficult to manage this - I will process this using the log viewers and it’s not simple when it’s pasted here. Please provide them as a complete text file.

sorry for this,
i am unaware of the fact that we can attach text file also.
i will attach text file for future problems if needed.