Ah, sorry misunderstood 
Itās the Door sensor from Neo, these are the details:
Manufacturer 0258 Shenzhen Neo Electronics Co., Ltd
Type / ID 0003:1082
Firmware Version3.61
Z-Wave Plus Node TypeACCESS_CONTROL_SENSOR
Basic Class
The channel for the Contact is shown as BINARY_SENSOR.
Thanks - Iāll update the channel to sensor_door so it will change type.
Chris
Dear experts,
I spend the whole weekend trying to connect Neo CoolCam PIR sensor to OH2.
I manage to get the device online, however, the sensor remains as āunknown deviceā.
What I read and understand - the device is added to the database, it only requires to be woken up (a couple of times) manually. So when I press the button on the back of the sensor, the LED turns on, but nothing is received by the controller (no messages in TRACE logging mode).
Could you please advice which troubleshooting steps should I take?
Thanks in advance!
Because it is a fairly new device you need to make sure you are on a recent snapshot zwave binding.
I tried both bindings, installing 2.2.0 snapshot in PaperUI and manually putting the latest jar into /addons directory.
The binding supposed to support the device, as in PaperUI under the supported devices I can find my node:
zwave:shenzhen_motionsensorin_00_000
@engy I have three now and they all ended up working fine however, I had two of them who were initially not linked correctly (the controller was not in the lifeline group).
So I just accepted them from the inbox and removed them. After that I rescanned and re-added and did the wake-up thing again.
What do you mean by āthe controller was not in the lifeline groupā?
And how to know if wake-up function is working properly?
I donāt know whether I use(d) the correct terms but there is a group which determines what devices receive all update about all device related events if the controller is not in this list it will not work. I was able to see this via habmin but you might be able to see it also via an other way.
Maybe you can just remove the thing from the paperui and try again?
See my device (I referred to that first association group):
@martinvw, Thanks for your support.
I removed the controller and the device from OH2 then added again via HABmin
The result is the same, log says:
2017-12-18 14:27:05.650 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling... 2017-12-18 14:27:05.654 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 2: Polling deferred until initialisation complete
And when I press the wake-up button - nothing is sent to the controller (at least nothing is reported in debug mode). Is that normal?
AFAIK it has to be woken up a lot of time and could help to do it closer to the controller. However I do agree that you would expect some logging there but I donāt know fur sure and cannot read my logs from here.
This is probably the first thing to work on. If there is nothing being sent (well, nothing being received) when you wake up the device, then nothing will work - no matter how many times itās woken up. I would suspect that maybe the device didnāt include properly.
By this, I guess you donāt mean that it was excluded and re-included as the device is still showing as node 2. I would expect that unless you have reset the controller completely (which is not necessary by the way) that if you exclude the device, and re-include it, that it should come up as node 3 (or 4 etc - depending on how many times you do this).
My suggestion is to exclude first - select the controller thing in HABmin, in the top right corner menu select Advanced, then select exclude mode in the same menu, then on the device click the button to exclude it (read the device manual to see exactly how this is done for the device you have).
Then do an include again - if it works, you should get node 3 showing up in the inbox. You may then need to wake the device up once or twice (or maybe more) after this to allow it to complete the initialisation. Wait 5 or 10 seconds between wakeupsā¦
See how that goesā¦
@chris, appreciate your support!
I already tried to exclude and include the node many times and the result was always the same - only node 2 was detected.
What could be the problem? It seems that my controller has hard reset after node exclusion or before inclusion.
I think itās unlikely that the controller is being hard reset - unless you are sending this command. Itās probably more likely that you are not actually excluding the device in the first place. I would suggest to enable debug logging so we can see exactly what is happening when you are doing this.
@chris, please see the exclusion debug log:
2017-12-20 19:09:16.207 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update received
2017-12-20 19:09:16.214 [DEBUG] [zwave.handler.ZWaveControllerHandler] - Controller Configuration update controller_exclude to true
2017-12-20 19:09:16.218 [DEBUG] [serialmessage.RemoveNodeMessageClass] - Setting controller into EXCLUSION mode.
2017-12-20 19:09:16.221 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2017-12-20 19:09:16.225 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
2017-12-20 19:09:16.228 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-12-20 19:09:16.231 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2017-12-20 19:09:16.234 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2017-12-20 19:09:16.237 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-12-20 19:09:16.240 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-12-20 19:09:16.244 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = RemoveNodeFromNetwork (0x4B), type = Request (0x00)
2017-12-20 19:09:16.248 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0x9C
2017-12-20 19:09:16.252 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4B 01 2C 9C
2017-12-20 19:09:16.256 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4B 01 2C 9C
2017-12-20 19:09:16.260 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-12-20 19:09:16.262 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-12-20 19:09:16.265 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06
2017-12-20 19:09:16.265 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1365: Transaction Start type RemoveNodeFromNetwork
2017-12-20 19:09:16.268 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 58<>70 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-12-20 19:09:16.268 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1365: [WAIT_REQUEST] requiresResponse=true callback: 44
2017-12-20 19:09:16.272 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-12-20 19:09:16.272 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2017-12-20 19:09:16.274 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2017-12-20 19:09:16.275 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2017-12-20 19:09:16.281 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4B 2C 01 00 00 9E
2017-12-20 19:09:16.284 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 4B 2C 01 00 00 9E
2017-12-20 19:09:16.286 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0x9E
2017-12-20 19:09:16.279 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2017-12-20 19:09:16.291 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Dec 20 19:09:21 CET 2017 - 5000ms
2017-12-20 19:09:16.288 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2017-12-20 19:09:16.298 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 1365: [WAIT_REQUEST] requiresResponse=true callback: 44
2017-12-20 19:09:16.300 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 1: Message payload = 2C 01 00 00
2017-12-20 19:09:16.301 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2017-12-20 19:09:16.301 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-12-20 19:09:16.303 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-12-20 19:09:16.304 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Dec 20 19:09:21 CET 2017 - 4986ms
2017-12-20 19:09:16.306 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 59<>69 : Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], dest=1, callback=44, payload=2C 01 00 00
2017-12-20 19:09:16.307 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start exclusion
2017-12-20 19:09:16.310 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], dest=1, callback=44, payload=2C 01 00 00
2017-12-20 19:09:21.291 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
2017-12-20 19:09:21.294 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 1365: Timeout at state WAIT_REQUEST. 3 retries remaining.
2017-12-20 19:09:21.295 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 1365: Transaction is current transaction, so clearing!!!!!
2017-12-20 19:09:21.298 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1365: Transaction CANCELLED
2017-12-20 19:09:21.300 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-12-20 19:09:21.302 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:1365 CANCELLED
2017-12-20 19:09:21.305 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-12-20 19:09:21.314 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2017-12-20 19:09:21.316 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2017-12-20 19:09:21.318 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-12-20 19:09:21.320 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage nothing
2017-12-20 19:09:21.322 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-12-20 19:09:21.560 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2017-12-20 19:09:21.566 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4B 2C 02 00 00 9D
2017-12-20 19:09:21.569 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 07 00 4B 2C 02 00 00 9D
2017-12-20 19:09:21.571 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0x9D
2017-12-20 19:09:21.573 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2017-12-20 19:09:21.575 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 2: Message payload = 2C 02 00 00
2017-12-20 19:09:21.578 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2017-12-20 19:09:21.580 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-12-20 19:09:21.583 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 60<>68 : Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], dest=2, callback=44, payload=2C 02 00 00
2017-12-20 19:09:21.586 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], dest=2, callback=44, payload=2C 02 00 00
2017-12-20 19:09:22.587 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2017-12-20 19:09:22.596 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 17 00 4B 2C 03 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 C7
2017-12-20 19:09:22.609 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 17 00 4B 2C 03 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 C7
2017-12-20 19:09:22.616 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0xC7
2017-12-20 19:09:22.618 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2017-12-20 19:09:22.628 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 3: Message payload = 2C 03 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84
2017-12-20 19:09:22.630 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2017-12-20 19:09:22.633 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-12-20 19:09:22.638 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 61<>67 : Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], dest=3, callback=44, payload=2C 03 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84
2017-12-20 19:09:22.643 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], dest=3, callback=44, payload=2C 03 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84
2017-12-20 19:09:22.649 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2017-12-20 19:09:22.667 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 17 00 4B 2C 06 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 C2
2017-12-20 19:09:22.672 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 17 00 4B 2C 06 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 C2
2017-12-20 19:09:22.674 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0xC2
2017-12-20 19:09:22.676 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2017-12-20 19:09:22.681 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 6: Message payload = 2C 06 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84
2017-12-20 19:09:22.682 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2017-12-20 19:09:22.685 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2017-12-20 19:09:22.690 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 62<>66 : Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], dest=6, callback=44, payload=2C 06 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84
2017-12-20 19:09:22.694 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], dest=6, callback=44, payload=2C 06 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84
2017-12-20 19:09:46.307 [DEBUG] [ve.internal.protocol.ZWaveController] - Ending inclusion mode.
2017-12-20 19:09:46.309 [DEBUG] [ve.internal.protocol.ZWaveController] - Stopping inclusion timer.
2017-12-20 19:09:46.312 [DEBUG] [serialmessage.RemoveNodeMessageClass] - Ending EXCLUSION mode.
2017-12-20 19:09:46.314 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2017-12-20 19:09:46.317 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
2017-12-20 19:09:46.319 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-12-20 19:09:46.322 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2017-12-20 19:09:46.324 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2017-12-20 19:09:46.327 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2017-12-20 19:09:46.329 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2017-12-20 19:09:46.332 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = RemoveNodeFromNetwork (0x4B), type = Request (0x00)
2017-12-20 19:09:46.335 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = 0x99
2017-12-20 19:09:46.339 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4B 05 2D 99
2017-12-20 19:09:46.342 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4B 05 2D 99
2017-12-20 19:09:46.345 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2017-12-20 19:09:46.347 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2017-12-20 19:09:46.347 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1366: Transaction Start type RemoveNodeFromNetwork
2017-12-20 19:09:46.349 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06
2017-12-20 19:09:46.350 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 1366: [WAIT_REQUEST] requiresResponse=true callback: 45
2017-12-20 19:09:46.351 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 63<>65 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-12-20 19:09:46.352 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2017-12-20 19:09:46.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
2017-12-20 19:09:46.354 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2017-12-20 19:09:46.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2017-12-20 19:09:46.361 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Dec 20 19:09:51 CET 2017 - 5000ms
2017-12-20 19:09:46.364 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 1366: [WAIT_REQUEST] requiresResponse=true callback: 45
2017-12-20 19:09:46.366 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2017-12-20 19:09:46.369 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Wed Dec 20 19:09:51 CET 2017 - 4992ms
2017-12-20 19:09:46.371 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller end exclusion
2017-12-20 19:09:51.361 [DEBUG] [sactionManager$ZWaveTransactionTimer] - XXXXXXXXX Timeout.......... 1 outstanding transactions
2017-12-20 19:09:51.363 [DEBUG] [sactionManager$ZWaveTransactionTimer] - NODE 255: TID 1366: Timeout at state WAIT_REQUEST. 3 retries remaining.
2017-12-20 19:09:51.365 [DEBUG] [sactionManager$ZWaveTransactionTimer] - TID 1366: Transaction is current transaction, so clearing!!!!!
2017-12-20 19:09:51.366 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 1366: Transaction CANCELLED
2017-12-20 19:09:51.372 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-12-20 19:09:51.375 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:1366 CANCELLED
2017-12-20 19:09:51.383 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2017-12-20 19:09:51.386 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2017-12-20 19:09:51.388 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!The exclude does look ok -:
Note that you also have to manually delete the thing as itās presumably now not linked to the node (this canāt be done automatically by the binding unfortunately).
I would be tempted to reset the device (check the manual for how to do this) then re-include it. I would expect it to come up with node 3 next time.
@chris, correct, the exclusion looks ok. However, when I include it again - itās appearing as node 2. And if repeat process, it continues with node 2.
Another strange observation - sometimes the device discovered in the inbox as Node 2, sometimes Z-Wave Node 2.
Please see the log:
2017-12-21 22:44:25.974 [DEBUG] [serialmessage.RemoveNodeMessageClass] - Remove Node: Node found for removal.
2017-12-21 22:44:25.978 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 01
2017-12-21 22:44:25.983 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 02 00 00
2017-12-21 22:44:25.987 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=RemoveNodeFromNetwork, callback id=0, expected=RemoveNodeFromNetwork, cancelled=false transaction complete!
2017-12-21 22:44:25.990 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-12-21 22:44:26.599 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 17 00 4B 01 03 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 EA
2017-12-21 22:44:26.611 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-12-21 22:44:26.615 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 17 00 4B 01 06 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 EF
2017-12-21 22:44:26.617 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 17 00 4B 01 03 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 EA
2017-12-21 22:44:26.623 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 17 00 4B 01 03 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 EA
2017-12-21 22:44:26.629 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 03 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84
2017-12-21 22:44:26.631 [DEBUG] [serialmessage.RemoveNodeMessageClass] - NODE 2: Removing slave.
2017-12-21 22:44:26.633 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2017-12-21 22:44:26.636 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 01
2017-12-21 22:44:26.641 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 03 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84
2017-12-21 22:44:26.644 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=RemoveNodeFromNetwork, callback id=0, expected=RemoveNodeFromNetwork, cancelled=false transaction complete!
2017-12-21 22:44:26.646 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-12-21 22:44:26.648 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-12-21 22:44:26.653 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 17 00 4B 01 06 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 EF
2017-12-21 22:44:26.659 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 17 00 4B 01 06 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 EF
2017-12-21 22:44:26.663 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 06 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84
2017-12-21 22:44:26.666 [DEBUG] [serialmessage.RemoveNodeMessageClass] - Remove Node: Done.
2017-12-21 22:44:26.668 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2017-12-21 22:44:26.672 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Excluding node.
2017-12-21 22:44:26.746 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 01
2017-12-21 22:44:26.753 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 06 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84
2017-12-21 22:44:26.756 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=RemoveNodeFromNetwork, callback id=0, expected=RemoveNodeFromNetwork, cancelled=false transaction complete!
2017-12-21 22:44:26.759 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-12-21 22:44:46.057 [DEBUG] [ve.internal.protocol.ZWaveController] - Ending inclusion mode.
2017-12-21 22:44:46.060 [DEBUG] [ve.internal.protocol.ZWaveController] - Stopping inclusion timer.
2017-12-21 22:44:46.062 [DEBUG] [serialmessage.RemoveNodeMessageClass] - Ending EXCLUSION mode.
2017-12-21 22:44:46.066 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-12-21 22:44:46.070 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4B 05 FE 4A
2017-12-21 22:44:46.074 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4B 05 FE 4A
2017-12-21 22:44:46.066 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-12-21 22:44:46.101 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller end exclusion
2017-12-21 22:44:48.809 [DEBUG] [ve.internal.protocol.ZWaveController] - Stopping inclusion timer.
2017-12-21 22:44:48.813 [DEBUG] [ve.internal.protocol.ZWaveController] - Neither inclusion nor exclusion was active!
2017-12-21 22:44:48.820 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - Starting ZWave inclusion scan for zwave:serial_zstick:UZB1
2017-12-21 22:44:48.824 [DEBUG] [ve.internal.protocol.ZWaveController] - ZWave controller start inclusion - mode 1
2017-12-21 22:44:48.827 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Setting controller into INCLUSION mode, highPower:true networkWide:false.
2017-12-21 22:44:48.835 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-12-21 22:44:51.077 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 2 attempts left!
2017-12-21 22:44:51.080 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2017-12-21 22:44:51.084 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
2017-12-21 22:44:51.088 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4B 05 FE 4A
2017-12-21 22:44:51.092 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4B 05 FE 4A
2017-12-21 22:44:54.725 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 16 00 49 84 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 6F
2017-12-21 22:44:54.734 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-12-21 22:44:54.741 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 16 00 49 84 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 6F
2017-12-21 22:44:54.749 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 16 00 49 84 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84 6F
2017-12-21 22:44:54.757 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84
2017-12-21 22:44:54.761 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 2: Application update request. Node information received.
2017-12-21 22:44:54.766 [DEBUG] [essage.ApplicationUpdateMessageClass] - NODE 2: Application update request. Node not known!
2017-12-21 22:44:54.770 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2017-12-21 22:44:54.776 [DEBUG] [wave.discovery.ZWaveDiscoveryService] - NODE 2: Device discovered
2017-12-21 22:44:54.786 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'zwave:device:UZB1:node2' to inbox.
2017-12-21 22:44:54.794 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Newly included node doesn't exist - initialising from start.
2017-12-21 22:44:54.798 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2017-12-21 22:44:54.814 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Init node thread start
2017-12-21 22:44:54.815 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], priority=High, dest=255, callback=0, payload=05 FE
2017-12-21 22:44:54.820 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=ApplicationUpdate[0x49], type=Request[0x00], priority=High, dest=255, callback=0, payload=84 02 10 04 07 01 5E 86 72 5A 73 80 31 71 30 70 85 59 84
2017-12-21 22:44:54.823 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=ApplicationUpdate, callback id=0, expected=RemoveNodeFromNetwork, cancelled=false MISMATCH
2017-12-21 22:44:54.933 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 2: Serializing from file /opt/openhab2/userdata/zwave/node2.xml
2017-12-21 22:44:54.936 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 2: Error serializing from file: file does not exist.
2017-12-21 22:44:54.939 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Starting initialisation from EMPTYNODE
2017-12-21 22:44:54.941 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2017-12-21 22:44:54.944 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2017-12-21 22:44:54.946 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: Initialisation starting
2017-12-21 22:44:54.948 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to PROTOINFO
2017-12-21 22:44:54.950 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2017-12-21 22:44:54.952 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2017-12-21 22:44:54.954 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: PROTOINFO - send IdentifyNode
2017-12-21 22:44:54.956 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 1
2017-12-21 22:44:54.958 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2017-12-21 22:44:54.961 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 2: Init node thread finished
2017-12-21 22:44:56.095 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 1 attempts left!
2017-12-21 22:44:56.098 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
2017-12-21 22:44:56.100 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 2
2017-12-21 22:44:56.103 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4B 05 FE 4A
2017-12-21 22:44:56.107 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4B 05 FE 4A
2017-12-21 22:45:01.110 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Timeout while sending message. Requeueing - 0 attempts left!
2017-12-21 22:45:01.112 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 3. Queue={}
2017-12-21 22:45:01.114 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 2
2017-12-21 22:45:01.117 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4B 05 FE 4A
2017-12-21 22:45:01.120 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4B 05 FE 4A
2017-12-21 22:45:06.125 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Too many retries. Discarding message: Message: class=RemoveNodeFromNetwork[0x4B], type=Request[0x00], priority=High, dest=255, callback=0, payload=05 FE
2017-12-21 22:45:06.128 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
2017-12-21 22:45:06.132 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 05 00 4A 81 01 30
2017-12-21 22:45:06.137 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 05 00 4A 81 01 30
2017-12-21 22:45:06.145 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 4A 01 01 00 00 B2
2017-12-21 22:45:06.153 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-12-21 22:45:06.158 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 4A 01 01 00 00 B2
2017-12-21 22:45:06.164 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 07 00 4A 01 01 00 00 B2
2017-12-21 22:45:06.170 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 01 00 00
2017-12-21 22:45:06.179 [DEBUG] [ol.serialmessage.AddNodeMessageClass] - Add Node: Learn ready.
2017-12-21 22:45:06.183 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInclusionEvent
2017-12-21 22:45:06.197 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=81 01
2017-12-21 22:45:06.203 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=AddNodeToNetwork[0x4A], type=Request[0x00], priority=High, dest=255, callback=0, payload=01 01 00 00
2017-12-21 22:45:06.208 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=AddNodeToNetwork, callback id=0, expected=AddNodeToNetwork, cancelled=false transaction complete!
2017-12-21 22:45:06.213 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-12-21 22:45:06.217 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 78ms/4190ms.
2017-12-21 22:45:06.220 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-12-21 22:45:06.225 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 41 02 B8
2017-12-21 22:45:06.229 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 41 02 B8
2017-12-21 22:45:06.240 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 09 01 41 00 00 00 03 00 00 B5
2017-12-21 22:45:06.248 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-12-21 22:45:06.254 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 01 41 00 00 00 03 00 00 B5
2017-12-21 22:45:06.261 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 01 41 00 00 00 03 00 00 B5
2017-12-21 22:45:06.269 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=IdentifyNode[0x41], type=Response[0x01], priority=High, dest=255, callback=0, payload=00 00 00 03 00 00
2017-12-21 22:45:06.274 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: ProtocolInfo
2017-12-21 22:45:06.278 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Listening = false
2017-12-21 22:45:06.283 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Routing = false
2017-12-21 22:45:06.287 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Beaming = false
2017-12-21 22:45:06.291 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Version = 1
2017-12-21 22:45:06.294 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: FLIRS = false
2017-12-21 22:45:06.298 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Security = false
2017-12-21 22:45:06.301 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Max Baud = 9600
2017-12-21 22:45:06.305 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Basic = Slave
2017-12-21 22:45:06.308 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Generic = Not Known
2017-12-21 22:45:06.312 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 2: Specific = Not Known
2017-12-21 22:45:06.315 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=IdentifyNode[0x41], type=Request[0x00], priority=High, dest=255, callback=0, payload=02
2017-12-21 22:45:06.318 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=IdentifyNode[0x41], type=Response[0x01], priority=High, dest=255, callback=0, payload=00 00 00 03 00 00
2017-12-21 22:45:06.320 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=IdentifyNode, callback id=0, expected=IdentifyNode, cancelled=false transaction complete!
2017-12-21 22:45:06.322 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-12-21 22:45:06.325 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={}
2017-12-21 22:45:06.327 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true)
2017-12-21 22:45:06.330 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 1.
2017-12-21 22:45:06.332 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 0.
2017-12-21 22:45:06.334 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - PROTOINFO: queue length(0), free to send(true)
2017-12-21 22:45:06.339 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false)
2017-12-21 22:45:06.341 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to INIT_NEIGHBORS
2017-12-21 22:45:06.343 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2017-12-21 22:45:06.345 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - INIT_NEIGHBORS try 0: stageAdvanced(true)
2017-12-21 22:45:06.347 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: INIT_NEIGHBORS - send RoutingInfo
2017-12-21 22:45:06.348 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 2: Request routing info
2017-12-21 22:45:06.351 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 1
2017-12-21 22:45:06.353 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2017-12-21 22:45:06.355 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 123ms/4190ms.
2017-12-21 22:45:06.357 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
2017-12-21 22:45:06.360 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 07 00 80 02 00 00 03 79
2017-12-21 22:45:06.362 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 07 00 80 02 00 00 03 79
2017-12-21 22:45:06.372 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 20 01 80 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 00 5E
2017-12-21 22:45:06.382 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-12-21 22:45:06.388 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 20 01 80 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 00 5E
2017-12-21 22:45:06.394 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 20 01 80 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 00 5E
2017-12-21 22:45:06.399 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=GetRoutingInfo[0x80], type=Response[0x01], priority=High, dest=255, callback=0, payload=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 00
2017-12-21 22:45:06.402 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 2: Got NodeRoutingInfo request.
2017-12-21 22:45:06.404 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 2: No neighbors reported
2017-12-21 22:45:06.406 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNetworkEvent
2017-12-21 22:45:06.410 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=GetRoutingInfo[0x80], type=Request[0x00], priority=High, dest=255, callback=0, payload=02 00 00 03
2017-12-21 22:45:06.415 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=GetRoutingInfo[0x80], type=Response[0x01], priority=High, dest=255, callback=0, payload=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 00
2017-12-21 22:45:06.418 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=GetRoutingInfo, callback id=0, expected=GetRoutingInfo, cancelled=false transaction complete!
2017-12-21 22:45:06.420 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-12-21 22:45:06.422 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - INIT_NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true)
2017-12-21 22:45:06.425 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 1.
2017-12-21 22:45:06.427 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 0.
2017-12-21 22:45:06.429 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - INIT_NEIGHBORS: queue length(0), free to send(true)
2017-12-21 22:45:06.431 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - INIT_NEIGHBORS try 1: stageAdvanced(false)
2017-12-21 22:45:06.434 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to FAILED_CHECK
2017-12-21 22:45:06.436 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2017-12-21 22:45:06.438 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true)
2017-12-21 22:45:06.442 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 2: Requesting IsFailedNode status from controller.
2017-12-21 22:45:06.446 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - queued packet. Queue length is 1
2017-12-21 22:45:06.448 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 2. Queue={}
2017-12-21 22:45:06.451 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 86ms/4190ms.
2017-12-21 22:45:06.453 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 1
2017-12-21 22:45:06.457 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 02 9B
2017-12-21 22:45:06.460 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 02 9B
2017-12-21 22:45:06.466 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 00 98
2017-12-21 22:45:06.471 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-12-21 22:45:06.475 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 62 00 98
2017-12-21 22:45:06.478 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 62 00 98
2017-12-21 22:45:06.481 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=IsFailedNodeID[0x62], type=Response[0x01], priority=High, dest=255, callback=0, payload=00
2017-12-21 22:45:06.484 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 2: Is currently marked as healthy by the controller
2017-12-21 22:45:06.488 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Sent Message: class=IsFailedNodeID[0x62], type=Request[0x00], priority=High, dest=255, callback=0, payload=02
2017-12-21 22:45:06.491 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: Recv Message: class=IsFailedNodeID[0x62], type=Response[0x01], priority=High, dest=255, callback=0, payload=00
2017-12-21 22:45:06.495 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Checking transaction complete: class=IsFailedNodeID, callback id=0, expected=IsFailedNodeID, cancelled=false transaction complete!
2017-12-21 22:45:06.498 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2017-12-21 22:45:06.501 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true)
2017-12-21 22:45:06.504 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - checking initialisation queue. Queue size 1.
2017-12-21 22:45:06.507 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - message removed from queue. Queue size 0.
2017-12-21 22:45:06.510 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - FAILED_CHECK: queue length(0), free to send(true)
2017-12-21 22:45:06.514 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false)
2017-12-21 22:45:06.517 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer - advancing to WAIT
2017-12-21 22:45:06.520 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveInitializationStateEvent
2017-12-21 22:45:06.524 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: loop - WAIT try 0: stageAdvanced(true)
2017-12-21 22:45:06.527 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: WAIT - Listening=false, FrequentlyListening=false
2017-12-21 22:45:06.530 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 2: Node advancer: WAIT - Still waiting!
2017-12-21 22:45:06.533 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 255: Response processed after 70ms/4190ms.
2017-12-21 22:45:06.535 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0
2017-12-21 22:45:06.537 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 02 02 72 04 25 34 82
2017-12-21 22:45:06.540 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 72 04 25 34 82
2017-12-21 22:45:06.550 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8
2017-12-21 22:45:06.554 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0
2017-12-21 22:45:06.557 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8
2017-12-21 22:45:06.562 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8
2017-12-21 22:45:06.565 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01
2017-12-21 22:45:06.568 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 2: Sent Data successfully placed on stack.I donāt think the device is excluding properly. It says it is, but it also sends a NIF after it has apparently been excluded.
Iām guessing that you didnāt reset the device as suggested above since there is only 5 seconds between the exclude and include? If not, I would suggest to do this.
Anyway, maybe this isnāt really where we should focus since the device is communicating and seems to send a NIF. Are you sure it doesnāt nothing when you manually wake the device up? ie thereās nothing in the log at all?
engy, not sure if it helps, but I have three door/window sensors from the same manufacturer. Was super close to returning them as they did not include properly (device unknown). However, this is how I got it to work: removed from the z-wave network using Aeon Z-Waveās stick functionality. Added them back via HABmin. Still not recognised at this point. Butā¦ pressed the button three times in quick succession, after z-wave inclusion was completed, and voila - thing is properly recognised now. In my case, it was just undocumented waking-up procedure that ate some good hours of my life trying to understand whatās wrong.
For one of the sensors I had to repeat the three presses procedure, as it did not go well on the first try.
Hope it does the trick for you, as well.
Wow, thanks a lot! The triple click did the trick! Just like the original 
Iām desperate and started losing hope to have z-wave working.
None of my Neo CoolCam z-wave sensors can initiate, not even 220V non-battery switch.
Confused.
Not sure where to look for a problem and how to troubleshoot?
Is it ZB1 ME Stick? Binding? Neo Sensors? RPi2?
Both Neo PIRs gives the following logs after triple code press:
2018-01-06 17:46:10.480 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2018-01-06 17:46:10.485 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0 2018-01-06 17:46:10.487 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 2018-01-06 17:46:10.488 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 2018-01-06 17:46:10.490 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 2018-01-06 17:46:10.492 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: Sent Data successfully placed on stack. 2018-01-06 17:46:14.872 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 2E 01 01 B8 7D 2018-01-06 17:46:14.877 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0 2018-01-06 17:46:14.880 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 2E 01 01 B8 00 00 73 2018-01-06 17:46:14.882 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 2E 01 01 B8 00 00 73 2018-01-06 17:46:14.884 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=2E 01 01 B8 2018-01-06 17:46:14.886 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 5: SendData Request. CallBack ID = 46, Status = Transmission complete, no ACK received(1) 2018-01-06 17:46:14.888 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 5: Is sleeping 2018-01-06 17:46:14.889 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 5: Putting message SendData in wakeup queue. 2018-01-06 17:46:14.891 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2018-01-06 17:46:14.892 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 5: Node advancer - MANUFACTURER: Transaction complete (SendData:Request) success(false) 2018-01-06 17:46:14.894 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 5: Putting message SendData in wakeup queue. 2018-01-06 17:46:14.896 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent 2018-01-06 17:46:14.897 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 5: Response processed after 4427ms/4671ms. 2018-01-06 17:46:14.900 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0 2018-01-06 17:46:14.903 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 5: Message already on the wake-up queue. Removing original. 2018-01-06 17:46:14.905 [DEBUG] [commandclass.ZWaveWakeUpCommandClass] - NODE 5: Putting message SendData in wakeup queue.
And Neo 220V switch gives:
2018-01-06 18:10:17.971 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 22, Status = Transmission complete, no ACK received(1) 2018-01-06 18:10:17.973 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: Got an error while sending data. Resending message. 2018-01-06 18:10:17.975 [DEBUG] [ve.internal.protocol.ZWaveController] - Message queued. Queue length = 1. Queue={} 2018-01-06 18:10:17.977 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2018-01-06 18:10:17.980 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 4: Node advancer - MANUFACTURER: Transaction complete (SendData:Request) success(false) 2018-01-06 18:10:17.982 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Response processed after 4175ms/4855ms. 2018-01-06 18:10:17.985 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - Took message from queue for sending. Queue length = 0 2018-01-06 18:10:17.990 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 04 02 72 04 25 17 A7 2018-01-06 18:10:17.994 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 4: Sending REQUEST Message = 01 09 00 13 04 02 72 04 25 17 A7 2018-01-06 18:10:18.009 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 2018-01-06 18:10:18.014 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0 2018-01-06 18:10:18.016 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 01 13 01 E8 2018-01-06 18:10:18.019 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 04 01 13 01 E8 2018-01-06 18:10:18.021 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Response[0x01], priority=High, dest=255, callback=0, payload=01 2018-01-06 18:10:18.023 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: Sent Data successfully placed on stack. 2018-01-06 18:10:22.139 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 17 01 01 9E 62 2018-01-06 18:10:22.143 [DEBUG] [ve.internal.protocol.ZWaveController] - Receive queue TAKE: Length=0 2018-01-06 18:10:22.145 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 09 00 13 17 01 01 9E 00 00 6C 2018-01-06 18:10:22.148 [DEBUG] [ve.internal.protocol.ZWaveController] - Process Message = 01 09 00 13 17 01 01 9E 00 00 6C 2018-01-06 18:10:22.150 [DEBUG] [ve.internal.protocol.ZWaveController] - Message: class=SendData[0x13], type=Request[0x00], priority=High, dest=255, callback=0, payload=17 01 01 9E 2018-01-06 18:10:22.152 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: SendData Request. CallBack ID = 23, Status = Transmission complete, no ACK received(1) 2018-01-06 18:10:22.154 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 4: Node is DEAD. 2018-01-06 18:10:22.155 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNodeStatusEvent 2018-01-06 18:10:22.157 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 4: Node Status event during initialisation - Node is DEAD 2018-01-06 18:10:22.158 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 4: Node Status event - Node is DEAD 2018-01-06 18:10:22.160 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 4: Node is DEAD. Dropping message. 2018-01-06 18:10:22.162 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent 2018-01-06 18:10:22.163 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 4: Node advancer - MANUFACTURER: Transaction complete (SendData:Request) success(false) 2018-01-06 18:10:22.165 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 4: Response processed after 4168ms/4855ms.