search

openhab / openhab1-addons

Add-ons for openHAB 1.x
Eclipse Public License 2.0
3.43k stars 1.69k forks source link

Problem with the zwave communication between controller and node #2416

Closed DrScr3w closed 9 years ago

DrScr3w commented 9 years ago

zwave: org.openhab.binding.zwave-1.7.0-SNAPSHOT habmin: org.openhab.io.habmin-1.7.0-SNAPSHOT Controller: Aeotec Z-Stick S2 Z-Wave USB Controller Device: POP_004308

Hi, i am new in zwave area ;) But i have a Problem with my first device. Now it is connect to the zwave network but now i can't get any informations.

2015-04-07 18:40:46.120 [DEBUG] [.zwave.internal.ZWaveActivator:36 ]- Z-Wave binding started. Version 1.7.0.201503080846 2015-04-07 18:40:46.167 [DEBUG] [.z.internal.ZWaveActiveBinding:175 ]- ConverterHandler not initialised. Polling disabled. 2015-04-07 18:40:46.229 [INFO ] [.z.internal.ZWaveActiveBinding:325 ]- Update config, port = COM3 2015-04-07 18:40:46.229 [INFO ] [.z.internal.ZWaveActiveBinding:330 ]- Update config, healtime = 2 2015-04-07 18:40:46.229 [INFO ] [.z.internal.ZWaveActiveBinding:348 ]- Update config, pollingQueue = 25 2015-04-07 18:40:46.229 [INFO ] [.z.internal.ZWaveActiveBinding:357 ]- Update config, aliveCheckPeriod = 120000 2015-04-07 18:40:46.229 [INFO ] [.z.internal.ZWaveActiveBinding:375 ]- Update config, setSUC = true 2015-04-07 18:40:46.229 [INFO ] [.z.internal.ZWaveActiveBinding:384 ]- Update config, softReset = true 2015-04-07 18:40:46.229 [INFO ] [.z.internal.ZWaveActiveBinding:393 ]- Update config, masterController = false 2015-04-07 18:40:46.229 [DEBUG] [.z.internal.ZWaveActiveBinding:282 ]- Initialising zwave binding 2015-04-07 18:40:46.370 [INFO ] [b.z.i.protocol.ZWaveController:147 ]- Starting Z-Wave controller 2015-04-07 18:40:46.370 [INFO ] [b.z.i.protocol.ZWaveController:155 ]- Z-Wave timeout is set to 5000ms. Soft reset is true. 2015-04-07 18:40:46.370 [INFO ] [b.z.i.protocol.ZWaveController:408 ]- Connecting to serial port COM3 2015-04-07 18:40:46.826 [DEBUG] [eController$ZWaveReceiveThread:1431]- Starting Z-Wave thread: Receive 2015-04-07 18:40:46.842 [INFO ] [b.z.i.protocol.ZWaveController:428 ]- Serial port is initialized 2015-04-07 18:40:46.842 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiSoftReset (0x08), type = Request (0x00) 2015-04-07 18:40:46.842 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 08 F4 2015-04-07 18:40:46.857 [DEBUG] [WaveController$ZWaveSendThread:1215]- Starting Z-Wave thread: Send 2015-04-07 18:40:46.857 [DEBUG] [b.z.i.protocol.ZWaveController:1172]- Starting Z-Wave thread: Input 2015-04-07 18:40:49.857 [DEBUG] [veController$WatchDogTimerTask:177 ]- Initialising network 2015-04-07 18:40:49.857 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetVersion (0x15), type = Request (0x00) 2015-04-07 18:40:49.857 [DEBUG] [b.z.i.protocol.ZWaveController:659 ]- Enqueueing message. Queue length = 0 2015-04-07 18:40:49.857 [DEBUG] [WaveController$ZWaveSendThread:1229]- Took message from queue for sending. Queue length = 0 2015-04-07 18:40:49.857 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 15 E9 2015-04-07 18:40:49.857 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = MemoryGetId (0x20), type = Request (0x00) 2015-04-07 18:40:49.857 [DEBUG] [b.z.i.protocol.ZWaveController:659 ]- Enqueueing message. Queue length = 1 2015-04-07 18:40:49.857 [DEBUG] [WaveController$ZWaveSendThread:1286]- NODE 255: Sending REQUEST Message = 01 03 00 15 E9 2015-04-07 18:40:49.857 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiGetCapabilities (0x07), type = Request (0x00) 2015-04-07 18:40:49.857 [DEBUG] [b.z.i.protocol.ZWaveController:659 ]- Enqueueing message. Queue length = 2 2015-04-07 18:40:49.873 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiSetTimeouts (0x06), type = Request (0x00) 2015-04-07 18:40:49.873 [DEBUG] [b.z.i.protocol.ZWaveController:659 ]- Enqueueing message. Queue length = 3 2015-04-07 18:40:49.873 [DEBUG] [i.p.s.GetSucNodeIdMessageClass:30 ]- Get SUC NodeID 2015-04-07 18:40:49.873 [DEBUG] [eController$ZWaveReceiveThread:1499]- Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 32 2E 37 38 00 01 9B 2015-04-07 18:40:49.873 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetSucNodeId (0x56), type = Request (0x00) 2015-04-07 18:40:49.873 [DEBUG] [b.z.i.protocol.ZWaveController:659 ]- Enqueueing message. Queue length = 4 2015-04-07 18:40:49.873 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:40:49.888 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:40:49.888 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 10 01 15 5A 2D 57 61 76 65 20 32 2E 37 38 00 01 9B 2015-04-07 18:40:49.888 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- Process Message = 01 10 01 15 5A 2D 57 61 76 65 20 32 2E 37 38 00 01 9B 2015-04-07 18:40:49.888 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- Message: class = GetVersion (0x15), type = Response (0x01), payload = 5A 2D 57 61 76 65 20 32 2E 37 38 00 01 2015-04-07 18:40:49.920 [DEBUG] [z.i.p.s.GetVersionMessageClass:39 ]- Got MessageGetVersion response. Version = Z-Wave 2.78, Library Type = 0x01 2015-04-07 18:40:49.920 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = GetVersion (0x15), type = Request (0x00), payload = 2015-04-07 18:40:49.920 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- Recv message Message: class = GetVersion (0x15), type = Response (0x01), payload = 5A 2D 57 61 76 65 20 32 2E 37 38 00 01 2015-04-07 18:40:49.920 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=GetVersion, expected=GetVersion, cancelled=false 2015-04-07 18:40:49.920 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:40:49.920 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:40:49.920 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:40:49.935 [DEBUG] [WaveController$ZWaveSendThread:1345]- NODE 255: Response processed after 78ms/78ms. 2015-04-07 18:40:49.935 [DEBUG] [WaveController$ZWaveSendThread:1229]- Took message from queue for sending. Queue length = 3 2015-04-07 18:40:49.935 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 20 DC 2015-04-07 18:40:49.935 [DEBUG] [WaveController$ZWaveSendThread:1286]- NODE 255: Sending REQUEST Message = 01 03 00 20 DC 2015-04-07 18:40:49.951 [DEBUG] [eController$ZWaveReceiveThread:1499]- Receive Message = 01 08 01 20 01 84 EA 7D 01 C5 2015-04-07 18:40:49.951 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:40:49.951 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:40:49.951 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 08 01 20 01 84 EA 7D 01 C5 2015-04-07 18:40:49.951 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- Process Message = 01 08 01 20 01 84 EA 7D 01 C5 2015-04-07 18:40:49.951 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- Message: class = MemoryGetId (0x20), type = Response (0x01), payload = 01 84 EA 7D 01 2015-04-07 18:40:49.951 [DEBUG] [.i.p.s.MemoryGetIdMessageClass:41 ]- Got MessageMemoryGetId response. Home id = 0x0184EA7D, Controller Node id = 1 2015-04-07 18:40:49.967 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = MemoryGetId (0x20), type = Request (0x00), payload = 2015-04-07 18:40:49.967 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- Recv message Message: class = MemoryGetId (0x20), type = Response (0x01), payload = 01 84 EA 7D 01 2015-04-07 18:40:49.967 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=MemoryGetId, expected=MemoryGetId, cancelled=false 2015-04-07 18:40:49.967 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:40:49.967 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:40:49.967 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:40:49.967 [DEBUG] [WaveController$ZWaveSendThread:1345]- NODE 255: Response processed after 32ms/78ms. 2015-04-07 18:40:49.967 [DEBUG] [WaveController$ZWaveSendThread:1229]- Took message from queue for sending. Queue length = 2 2015-04-07 18:40:49.967 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 07 FB 2015-04-07 18:40:49.967 [DEBUG] [WaveController$ZWaveSendThread:1286]- NODE 255: Sending REQUEST Message = 01 03 00 07 FB 2015-04-07 18:40:49.982 [DEBUG] [eController$ZWaveReceiveThread:1499]- Receive Message = 01 2B 01 07 03 07 00 86 00 02 00 01 FE 80 FE 88 0F 00 00 00 FB 97 7F 82 07 00 00 80 00 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 C2 2015-04-07 18:40:49.998 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:40:49.998 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:40:50.013 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 2B 01 07 03 07 00 86 00 02 00 01 FE 80 FE 88 0F 00 00 00 FB 97 7F 82 07 00 00 80 00 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 C2 2015-04-07 18:40:50.013 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- Process Message = 01 2B 01 07 03 07 00 86 00 02 00 01 FE 80 FE 88 0F 00 00 00 FB 97 7F 82 07 00 00 80 00 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 C2 2015-04-07 18:40:50.029 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- Message: class = SerialApiGetCapabilities (0x07), type = Response (0x01), payload = 03 07 00 86 00 02 00 01 FE 80 FE 88 0F 00 00 00 FB 97 7F 82 07 00 00 80 00 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2015-04-07 18:40:50.029 [DEBUG] [ApiGetCapabilitiesMessageClass:45 ]- API Version = 3.7 2015-04-07 18:40:50.029 [DEBUG] [ApiGetCapabilitiesMessageClass:46 ]- Manufacture ID = 0x86 2015-04-07 18:40:50.029 [DEBUG] [ApiGetCapabilitiesMessageClass:47 ]- Device Type = 0x2 2015-04-07 18:40:50.029 [DEBUG] [ApiGetCapabilitiesMessageClass:48 ]- Device ID = 0x1 2015-04-07 18:40:50.029 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: SerialApiGetInitData 2015-04-07 18:40:50.029 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: SerialApiApplicationNodeInfo 2015-04-07 18:40:50.029 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: ApplicationCommandHandler 2015-04-07 18:40:50.029 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: GetControllerCapabilities 2015-04-07 18:40:50.029 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: SerialApiSetTimeouts 2015-04-07 18:40:50.029 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: SerialApiGetCapabilities 2015-04-07 18:40:50.029 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: SerialApiSoftReset 2015-04-07 18:40:50.029 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: RfReceiveMode 2015-04-07 18:40:50.029 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: SendNodeInfo 2015-04-07 18:40:50.029 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: SendData 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: SendDataMulti 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: GetVersion 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: SendDataAbort 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: RfPowerLevelSet 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: SendDataMeta 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: GetRandom 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: MemoryGetId 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: MemoryGetByte 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: MemoryPutByte 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: ReadMemory 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: WriteMemory 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: IdentifyNode 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: SetDefault 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: ReplicationCommandComplete 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: ReplicationSendData 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: AssignReturnRoute 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: DeleteReturnRoute 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: RequestNodeNeighborUpdate 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: ApplicationUpdate 2015-04-07 18:40:50.045 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: AddNodeToNetwork 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: RemoveNodeFromNetwork 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: ControllerChange 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: SetLearnMode 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: AssignSucReturnRoute 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: EnableSuc 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: RequestNetworkUpdate 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: SetSucNodeID 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: DeleteSUCReturnRoute 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: GetSucNodeId 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: SendSucId 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: RequestNodeNeighborUpdateOptions 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: RequestNodeInfo 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: RemoveFailedNodeID 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: IsFailedNodeID 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: ReplaceFailedNode 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: GetRoutingInfo 2015-04-07 18:40:50.060 [DEBUG] [ApiGetCapabilitiesMessageClass:59 ]- Supports: LockRoute 2015-04-07 18:40:50.060 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = SerialApiGetCapabilities (0x07), type = Request (0x00), payload = 2015-04-07 18:40:50.076 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- Recv message Message: class = SerialApiGetCapabilities (0x07), type = Response (0x01), payload = 03 07 00 86 00 02 00 01 FE 80 FE 88 0F 00 00 00 FB 97 7F 82 07 00 00 80 00 80 00 00 00 00 00 00 00 00 00 00 00 00 00 00 2015-04-07 18:40:50.076 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=SerialApiGetCapabilities, expected=SerialApiGetCapabilities, cancelled=false 2015-04-07 18:40:50.076 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:40:50.076 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:40:50.076 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:40:50.076 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiGetInitData (0x02), type = Request (0x00) 2015-04-07 18:40:50.076 [DEBUG] [b.z.i.protocol.ZWaveController:659 ]- Enqueueing message. Queue length = 3 2015-04-07 18:40:50.076 [DEBUG] [WaveController$ZWaveSendThread:1345]- NODE 255: Response processed after 109ms/109ms. 2015-04-07 18:40:50.076 [DEBUG] [WaveController$ZWaveSendThread:1229]- Took message from queue for sending. Queue length = 2 2015-04-07 18:40:50.076 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 05 00 06 96 0F 65 2015-04-07 18:40:50.076 [DEBUG] [WaveController$ZWaveSendThread:1286]- NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 2015-04-07 18:40:50.092 [DEBUG] [eController$ZWaveReceiveThread:1499]- Receive Message = 01 05 01 06 96 0F 64 2015-04-07 18:40:50.092 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:40:50.092 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:40:50.092 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 05 01 06 96 0F 64 2015-04-07 18:40:50.092 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- Process Message = 01 05 01 06 96 0F 64 2015-04-07 18:40:50.092 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- Message: class = SerialApiSetTimeouts (0x06), type = Response (0x01), payload = 96 0F 2015-04-07 18:40:50.092 [DEBUG] [rialApiSetTimeoutsMessageClass:40 ]- Got SerialApiSetTimeouts response. ACK=150, BYTE=15 2015-04-07 18:40:50.092 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = SerialApiSetTimeouts (0x06), type = Request (0x00), payload = 96 0F 2015-04-07 18:40:50.092 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- Recv message Message: class = SerialApiSetTimeouts (0x06), type = Response (0x01), payload = 96 0F 2015-04-07 18:40:50.092 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=SerialApiSetTimeouts, expected=SerialApiSetTimeouts, cancelled=false 2015-04-07 18:40:50.092 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:40:50.092 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:40:50.092 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:40:50.092 [DEBUG] [WaveController$ZWaveSendThread:1345]- NODE 255: Response processed after 16ms/109ms. 2015-04-07 18:40:50.107 [DEBUG] [WaveController$ZWaveSendThread:1229]- Took message from queue for sending. Queue length = 1 2015-04-07 18:40:50.107 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 56 AA 2015-04-07 18:40:50.107 [DEBUG] [WaveController$ZWaveSendThread:1286]- NODE 255: Sending REQUEST Message = 01 03 00 56 AA 2015-04-07 18:40:50.107 [DEBUG] [eController$ZWaveReceiveThread:1499]- Receive Message = 01 04 01 56 01 AD 2015-04-07 18:40:50.107 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:40:50.107 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:40:50.107 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 56 01 AD 2015-04-07 18:40:50.107 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- Process Message = 01 04 01 56 01 AD 2015-04-07 18:40:50.107 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- Message: class = GetSucNodeId (0x56), type = Response (0x01), payload = 01 2015-04-07 18:40:50.123 [DEBUG] [i.p.s.GetSucNodeIdMessageClass:41 ]- Got SUC NodeID response. 2015-04-07 18:40:50.123 [DEBUG] [i.p.s.GetSucNodeIdMessageClass:44 ]- NODE 1: Node is SUC. 2015-04-07 18:40:50.123 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = GetSucNodeId (0x56), type = Request (0x00), payload = 2015-04-07 18:40:50.123 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- Recv message Message: class = GetSucNodeId (0x56), type = Response (0x01), payload = 01 2015-04-07 18:40:50.123 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=GetSucNodeId, expected=GetSucNodeId, cancelled=false 2015-04-07 18:40:50.123 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:40:50.123 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:40:50.123 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:40:50.123 [DEBUG] [WaveController$ZWaveSendThread:1345]- NODE 255: Response processed after 16ms/109ms. 2015-04-07 18:40:50.123 [DEBUG] [rollerCapabilitiesMessageClass:41 ]- Creating GET_CONTROLLER_CAPABILITIES message 2015-04-07 18:40:50.123 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetControllerCapabilities (0x05), type = Request (0x00) 2015-04-07 18:40:50.123 [DEBUG] [b.z.i.protocol.ZWaveController:659 ]- Enqueueing message. Queue length = 2 2015-04-07 18:40:50.123 [DEBUG] [WaveController$ZWaveSendThread:1229]- Took message from queue for sending. Queue length = 1 2015-04-07 18:40:50.123 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 02 FE 2015-04-07 18:40:50.123 [DEBUG] [WaveController$ZWaveSendThread:1286]- NODE 255: Sending REQUEST Message = 01 03 00 02 FE 2015-04-07 18:40:50.185 [DEBUG] [eController$ZWaveReceiveThread:1499]- Receive Message = 01 25 01 02 05 08 1D 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 03 01 CA 2015-04-07 18:40:50.201 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:40:50.201 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:40:50.201 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 25 01 02 05 08 1D 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 03 01 CA 2015-04-07 18:40:50.201 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- Process Message = 01 25 01 02 05 08 1D 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 03 01 CA 2015-04-07 18:40:50.201 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- Message: class = SerialApiGetInitData (0x02), type = Response (0x01), payload = 05 08 1D 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 03 01 2015-04-07 18:40:50.201 [DEBUG] [rialApiGetInitDataMessageClass:39 ]- Got MessageSerialApiGetInitData response. 2015-04-07 18:40:50.201 [INFO ] [rialApiGetInitDataMessageClass:57 ]- NODE 1: Node found 2015-04-07 18:40:50.217 [INFO ] [rialApiGetInitDataMessageClass:65 ]- ZWave Controller using Controller API 2015-04-07 18:40:50.217 [INFO ] [rialApiGetInitDataMessageClass:66 ]- ZWave Controller is Primary Controller 2015-04-07 18:40:50.217 [INFO ] [rialApiGetInitDataMessageClass:67 ]- ------------Number of Nodes Found Registered to ZWave Controller------------ 2015-04-07 18:40:50.217 [INFO ] [rialApiGetInitDataMessageClass:68 ]- # Nodes = 1 2015-04-07 18:40:50.217 [INFO ] [rialApiGetInitDataMessageClass:69 ]- ---------------------------------------------------------------------------- 2015-04-07 18:40:50.217 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = SerialApiGetInitData (0x02), type = Request (0x00), payload = 2015-04-07 18:40:50.217 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- Recv message Message: class = SerialApiGetInitData (0x02), type = Response (0x01), payload = 05 08 1D 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 03 01 2015-04-07 18:40:50.217 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=SerialApiGetInitData, expected=SerialApiGetInitData, cancelled=false 2015-04-07 18:40:50.217 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:40:50.217 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:40:50.217 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:40:50.217 [DEBUG] [WaveController$ZWaveSendThread:1345]- NODE 255: Response processed after 94ms/109ms. 2015-04-07 18:40:50.998 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:138 ]- NODE 1: Serializing from file etc\zwave\node1.xml 2015-04-07 18:40:51.107 [DEBUG] [b.z.i.protocol.ZWaveController:308 ]- NODE 1: Restored from config. 2015-04-07 18:40:51.201 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 1: Node advancer - EMPTYNODE: queue length(0), free to send(true) 2015-04-07 18:40:51.201 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1093]- NODE 1: Initialisation retry timer started 5000 2015-04-07 18:40:51.201 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 1: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false) 2015-04-07 18:40:51.201 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:338 ]- NODE 1: Node advancer: Initialisation starting 2015-04-07 18:40:51.201 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:855 ]- NODE 1: Node advancer - advancing to PROTOINFO 2015-04-07 18:40:51.217 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 1: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true) 2015-04-07 18:40:51.217 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:347 ]- NODE 1: Node advancer: PROTOINFO - send IdentifyNode 2015-04-07 18:40:51.217 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = IdentifyNode (0x41), type = Request (0x00) 2015-04-07 18:40:51.217 [DEBUG] [b.z.i.protocol.ZWaveController:659 ]- Enqueueing message. Queue length = 2 2015-04-07 18:40:51.217 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240 ]- NODE 1: Node advancer - queued packet. Queue length is 1 2015-04-07 18:40:51.217 [DEBUG] [WaveController$ZWaveSendThread:1229]- Took message from queue for sending. Queue length = 1 2015-04-07 18:40:51.217 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 05 F9 2015-04-07 18:40:51.217 [DEBUG] [WaveController$ZWaveSendThread:1286]- NODE 255: Sending REQUEST Message = 01 03 00 05 F9 2015-04-07 18:40:51.232 [DEBUG] [eController$ZWaveReceiveThread:1499]- Receive Message = 01 04 01 05 1C E3 2015-04-07 18:40:51.236 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:40:51.236 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:40:51.237 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 05 1C E3 2015-04-07 18:40:51.239 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- Process Message = 01 04 01 05 1C E3 2015-04-07 18:40:51.240 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- Message: class = GetControllerCapabilities (0x05), type = Response (0x01), payload = 1C 2015-04-07 18:40:51.242 [DEBUG] [rollerCapabilitiesMessageClass:55 ]- Controller is secondary = false 2015-04-07 18:40:51.243 [DEBUG] [rollerCapabilitiesMessageClass:56 ]- Controller is on other network = false 2015-04-07 18:40:51.244 [DEBUG] [rollerCapabilitiesMessageClass:57 ]- Node ID Server is present = false 2015-04-07 18:40:51.245 [DEBUG] [rollerCapabilitiesMessageClass:58 ]- Controller is real primary = true 2015-04-07 18:40:51.246 [DEBUG] [rollerCapabilitiesMessageClass:59 ]- Controller is SUC = true 2015-04-07 18:40:51.248 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = GetControllerCapabilities (0x05), type = Request (0x00), payload = 2015-04-07 18:40:51.250 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- Recv message Message: class = GetControllerCapabilities (0x05), type = Response (0x01), payload = 1C 2015-04-07 18:40:51.251 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=GetControllerCapabilities, expected=GetControllerCapabilities, cancelled=false 2015-04-07 18:40:51.253 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:40:51.254 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:40:51.255 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:40:51.256 [DEBUG] [WaveController$ZWaveSendThread:1345]- NODE 255: Response processed after 39ms/109ms. 2015-04-07 18:40:51.257 [DEBUG] [WaveController$ZWaveSendThread:1229]- Took message from queue for sending. Queue length = 0 2015-04-07 18:40:51.258 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 00 41 01 BB 2015-04-07 18:40:51.260 [DEBUG] [WaveController$ZWaveSendThread:1286]- NODE 255: Sending REQUEST Message = 01 04 00 41 01 BB 2015-04-07 18:40:51.265 [DEBUG] [eController$ZWaveReceiveThread:1499]- Receive Message = 01 09 01 41 92 16 00 02 02 01 33 2015-04-07 18:40:51.270 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:40:51.270 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:40:51.274 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 09 01 41 92 16 00 02 02 01 33 2015-04-07 18:40:51.276 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- Process Message = 01 09 01 41 92 16 00 02 02 01 33 2015-04-07 18:40:51.277 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- Message: class = IdentifyNode (0x41), type = Response (0x01), payload = 92 16 00 02 02 01 2015-04-07 18:40:51.279 [DEBUG] [i.p.s.IdentifyNodeMessageClass:52 ]- NODE 1: ProtocolInfo 2015-04-07 18:40:51.281 [DEBUG] [i.p.s.IdentifyNodeMessageClass:61 ]- NODE 1: Listening = true 2015-04-07 18:40:51.282 [DEBUG] [i.p.s.IdentifyNodeMessageClass:62 ]- NODE 1: Routing = false 2015-04-07 18:40:51.283 [DEBUG] [i.p.s.IdentifyNodeMessageClass:63 ]- NODE 1: Version = 3 2015-04-07 18:40:51.284 [DEBUG] [i.p.s.IdentifyNodeMessageClass:64 ]- NODE 1: FLIRS = false 2015-04-07 18:40:51.286 [DEBUG] [i.p.s.IdentifyNodeMessageClass:76 ]- NODE 1: Basic = Static Controller 2015-04-07 18:40:51.287 [DEBUG] [i.p.s.IdentifyNodeMessageClass:83 ]- NODE 1: Generic = Static Controller 2015-04-07 18:40:51.289 [DEBUG] [i.p.s.IdentifyNodeMessageClass:90 ]- NODE 1: Specific = PC Controller 2015-04-07 18:40:51.292 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:224 ]- NODE 1: Creating new instance of command class NO_OPERATION 2015-04-07 18:40:51.294 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:224 ]- NODE 1: Creating new instance of command class BASIC 2015-04-07 18:40:51.296 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 01 2015-04-07 18:40:51.298 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- Recv message Message: class = IdentifyNode (0x41), type = Response (0x01), payload = 92 16 00 02 02 01 2015-04-07 18:40:51.299 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=IdentifyNode, expected=IdentifyNode, cancelled=false 2015-04-07 18:40:51.300 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:40:51.302 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:40:51.303 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:40:51.305 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1000]- NODE 1: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true) 2015-04-07 18:40:51.306 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:201 ]- NODE 1: Node advancer - checking initialisation queue. Queue size 1. 2015-04-07 18:40:51.308 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ]- NODE 1: Node advancer - message removed from queue. Queue size 0. 2015-04-07 18:40:51.310 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 1: Node advancer - PROTOINFO: queue length(0), free to send(true) 2015-04-07 18:40:51.311 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1093]- NODE 1: Initialisation retry timer started 5000 2015-04-07 18:40:51.313 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 1: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false) 2015-04-07 18:40:51.314 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:855 ]- NODE 1: Node advancer - advancing to NEIGHBORS 2015-04-07 18:40:51.315 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 1: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true) 2015-04-07 18:40:51.316 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:357 ]- NODE 1: Node advancer: NEIGHBORS - send RoutingInfo 2015-04-07 18:40:51.320 [DEBUG] [p.s.GetRoutingInfoMessageClass:29 ]- NODE 1: Request routing info 2015-04-07 18:40:51.321 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetRoutingInfo (0x80), type = Request (0x00) 2015-04-07 18:40:51.322 [DEBUG] [b.z.i.protocol.ZWaveController:659 ]- Enqueueing message. Queue length = 1 2015-04-07 18:40:51.323 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240 ]- NODE 1: Node advancer - queued packet. Queue length is 1 2015-04-07 18:40:51.324 [DEBUG] [WaveController$ZWaveSendThread:1345]- NODE 255: Response processed after 63ms/109ms. 2015-04-07 18:40:51.325 [DEBUG] [WaveController$ZWaveSendThread:1229]- Took message from queue for sending. Queue length = 0 2015-04-07 18:40:51.327 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 07 00 80 01 00 00 03 7A 2015-04-07 18:40:51.329 [DEBUG] [WaveController$ZWaveSendThread:1286]- NODE 255: Sending REQUEST Message = 01 07 00 80 01 00 00 03 7A 2015-04-07 18:40:51.357 [DEBUG] [eController$ZWaveReceiveThread:1499]- 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 2015-04-07 18:40:51.363 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:40:51.364 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:40:51.367 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- 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 2015-04-07 18:40:51.370 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- 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 2015-04-07 18:40:51.373 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- Message: class = GetRoutingInfo (0x80), type = Response (0x01), 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 2015-04-07 18:40:51.374 [DEBUG] [p.s.GetRoutingInfoMessageClass:47 ]- NODE 1: Got NodeRoutingInfo request. 2015-04-07 18:40:51.375 [DEBUG] [p.s.GetRoutingInfoMessageClass:71 ]- NODE 1: No neighbors reported 2015-04-07 18:40:51.382 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveNetworkEvent 2015-04-07 18:40:51.384 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:40:51.388 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 01 00 00 03 2015-04-07 18:40:51.391 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- Recv message Message: class = GetRoutingInfo (0x80), type = Response (0x01), 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 2015-04-07 18:40:51.392 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=GetRoutingInfo, expected=GetRoutingInfo, cancelled=false 2015-04-07 18:40:51.393 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:40:51.394 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:40:51.395 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:40:51.396 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1000]- NODE 1: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true) 2015-04-07 18:40:51.398 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:201 ]- NODE 1: Node advancer - checking initialisation queue. Queue size 1. 2015-04-07 18:40:51.399 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ]- NODE 1: Node advancer - message removed from queue. Queue size 0. 2015-04-07 18:40:51.401 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 1: Node advancer - NEIGHBORS: queue length(0), free to send(true) 2015-04-07 18:40:51.402 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1093]- NODE 1: Initialisation retry timer started 5000 2015-04-07 18:40:51.403 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 1: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false) 2015-04-07 18:40:51.404 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:855 ]- NODE 1: Node advancer - advancing to FAILED_CHECK 2015-04-07 18:40:51.405 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 1: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true) 2015-04-07 18:40:51.407 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:366 ]- NODE 1: Node advancer: FAILED_CHECK - Controller - terminating initialisation 2015-04-07 18:40:51.408 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 1: Node advancer: loop - DONE try 0: stageAdvanced(true) 2015-04-07 18:40:51.409 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:107 ]- NODE 1: Serializing to file etc\zwave\node1.xml 2015-04-07 18:40:51.690 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:814 ]- NODE 1: Node advancer: Initialisation complete! 2015-04-07 18:40:51.692 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveInitializationCompletedEvent 2015-04-07 18:40:51.692 [DEBUG] [.z.internal.ZWaveActiveBinding:425 ]- NODE 1: ZWaveIncomingEvent Called, Network Event, Init Done. Setting device ready. 2015-04-07 18:40:51.693 [DEBUG] [z.internal.ZWaveNetworkMonitor:730 ]- Network initialised - starting network monitor. 2015-04-07 18:40:51.695 [DEBUG] [WaveController$ZWaveSendThread:1345]- NODE 255: Response processed after 365ms/365ms. 2015-04-07 18:41:08.838 [DEBUG] [.b.z.i.p.s.AddNodeMessageClass:43 ]- Setting controller into INCLUSION mode. 2015-04-07 18:41:08.840 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = AddNodeToNetwork (0x4A), type = Request (0x00) 2015-04-07 18:41:08.841 [DEBUG] [b.z.i.protocol.ZWaveController:659 ]- Enqueueing message. Queue length = 1 2015-04-07 18:41:08.841 [DEBUG] [WaveController$ZWaveSendThread:1229]- Took message from queue for sending. Queue length = 0 2015-04-07 18:41:08.844 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 05 00 4A 81 FF CE 2015-04-07 18:41:08.846 [DEBUG] [WaveController$ZWaveSendThread:1286]- NODE 255: Sending REQUEST Message = 01 05 00 4A 81 FF CE 2015-04-07 18:41:08.852 [DEBUG] [eController$ZWaveReceiveThread:1499]- Receive Message = 01 07 00 4A FF 01 00 00 4C 2015-04-07 18:41:08.855 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:41:08.856 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:41:08.858 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 07 00 4A FF 01 00 00 4C 2015-04-07 18:41:08.859 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- Process Message = 01 07 00 4A FF 01 00 00 4C 2015-04-07 18:41:08.860 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 01 00 00 2015-04-07 18:41:08.861 [DEBUG] [.b.z.i.p.s.AddNodeMessageClass:72 ]- Add Node: Learn ready. 2015-04-07 18:41:08.864 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveInclusionEvent 2015-04-07 18:41:08.865 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:41:08.867 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = 81 FF 2015-04-07 18:41:08.868 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- Recv message Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 01 00 00 2015-04-07 18:41:08.869 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=AddNodeToNetwork, expected=AddNodeToNetwork, cancelled=false 2015-04-07 18:41:08.869 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:41:08.870 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:41:08.871 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:41:08.872 [DEBUG] [WaveController$ZWaveSendThread:1345]- NODE 255: Response processed after 25ms/365ms. 2015-04-07 18:41:12.145 [DEBUG] [eController$ZWaveReceiveThread:1499]- Receive Message = 01 07 00 4A FF 02 00 00 4F 2015-04-07 18:41:12.147 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:41:12.147 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:41:12.149 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 07 00 4A FF 02 00 00 4F 2015-04-07 18:41:12.150 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- Process Message = 01 07 00 4A FF 02 00 00 4F 2015-04-07 18:41:12.151 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 02 00 00 2015-04-07 18:41:12.151 [DEBUG] [.b.z.i.p.s.AddNodeMessageClass:76 ]- Add Node: New node found. 2015-04-07 18:41:12.152 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = 81 FF 2015-04-07 18:41:12.153 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- Recv message Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 02 00 00 2015-04-07 18:41:12.154 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=AddNodeToNetwork, expected=AddNodeToNetwork, cancelled=false 2015-04-07 18:41:12.154 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:41:12.155 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:41:12.156 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:41:12.305 [DEBUG] [eController$ZWaveReceiveThread:1499]- Receive Message = 01 14 00 4A FF 03 04 0D 04 A1 07 20 30 71 31 70 85 80 84 72 86 A3 2015-04-07 18:41:12.310 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:41:12.310 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:41:12.313 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 14 00 4A FF 03 04 0D 04 A1 07 20 30 71 31 70 85 80 84 72 86 A3 2015-04-07 18:41:12.315 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- Process Message = 01 14 00 4A FF 03 04 0D 04 A1 07 20 30 71 31 70 85 80 84 72 86 A3 2015-04-07 18:41:12.319 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 03 04 0D 04 A1 07 20 30 71 31 70 85 80 84 72 86 2015-04-07 18:41:12.320 [DEBUG] [.b.z.i.p.s.AddNodeMessageClass:79 ]- NODE 4: Adding slave. 2015-04-07 18:41:12.320 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveInclusionEvent 2015-04-07 18:41:12.321 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:41:12.323 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = 81 FF 2015-04-07 18:41:12.325 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- Recv message Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 03 04 0D 04 A1 07 20 30 71 31 70 85 80 84 72 86 2015-04-07 18:41:12.326 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=AddNodeToNetwork, expected=AddNodeToNetwork, cancelled=false 2015-04-07 18:41:12.326 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:41:12.327 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:41:12.328 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:41:12.686 [DEBUG] [eController$ZWaveReceiveThread:1499]- Receive Message = 01 07 00 4A FF 05 04 00 4C 2015-04-07 18:41:12.691 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:41:12.691 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:41:12.693 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 07 00 4A FF 05 04 00 4C 2015-04-07 18:41:12.694 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- Process Message = 01 07 00 4A FF 05 04 00 4C 2015-04-07 18:41:12.696 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 05 04 00 2015-04-07 18:41:12.697 [DEBUG] [.b.z.i.p.s.AddNodeMessageClass:87 ]- Add Node: Protocol done. 2015-04-07 18:41:12.698 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = 81 FF 2015-04-07 18:41:12.699 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- Recv message Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 05 04 00 2015-04-07 18:41:12.700 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=AddNodeToNetwork, expected=AddNodeToNetwork, cancelled=false 2015-04-07 18:41:12.701 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:41:12.701 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:41:12.702 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:41:38.844 [DEBUG] [.z.i.config.ZWaveConfiguration:1281]- Ending inclusion mode. 2015-04-07 18:41:38.845 [DEBUG] [.z.i.config.ZWaveConfiguration:1304]- Stopping inclusion timer. 2015-04-07 18:41:38.845 [DEBUG] [.b.z.i.p.s.AddNodeMessageClass:57 ]- Ending INCLUSION mode. 2015-04-07 18:41:38.846 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = AddNodeToNetwork (0x4A), type = Request (0x00) 2015-04-07 18:41:38.847 [DEBUG] [b.z.i.protocol.ZWaveController:659 ]- Enqueueing message. Queue length = 1 2015-04-07 18:41:38.847 [DEBUG] [WaveController$ZWaveSendThread:1229]- Took message from queue for sending. Queue length = 0 2015-04-07 18:41:38.848 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 00 4A 05 B4 2015-04-07 18:41:38.849 [DEBUG] [WaveController$ZWaveSendThread:1286]- NODE 255: Sending REQUEST Message = 01 04 00 4A 05 B4 2015-04-07 18:41:38.903 [DEBUG] [eController$ZWaveReceiveThread:1499]- Receive Message = 01 07 00 4A FF 06 04 00 4F 2015-04-07 18:41:38.905 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:41:38.905 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:41:38.906 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 07 00 4A FF 06 04 00 4F 2015-04-07 18:41:38.907 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- Process Message = 01 07 00 4A FF 06 04 00 4F 2015-04-07 18:41:38.908 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 06 04 00 2015-04-07 18:41:38.909 [DEBUG] [.b.z.i.p.s.AddNodeMessageClass:90 ]- Add Node: Done. 2015-04-07 18:41:38.910 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveInclusionEvent 2015-04-07 18:41:38.910 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:41:38.911 [DEBUG] [.z.i.config.ZWaveConfiguration:1304]- Stopping inclusion timer. 2015-04-07 18:41:38.912 [ERROR] [.z.i.config.ZWaveConfiguration:1312]- Neither inclusion nor exclusion was active! 2015-04-07 18:41:38.913 [DEBUG] [b.z.i.protocol.ZWaveController:685 ]- NODE 4: Including node. 2015-04-07 18:41:38.916 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = 05 2015-04-07 18:41:38.916 [DEBUG] [b.z.i.protocol.ZWaveController:532 ]- NODE 4: Init node thread start 2015-04-07 18:41:38.917 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- Recv message Message: class = AddNodeToNetwork (0x4A), type = Request (0x00), payload = FF 06 04 00 2015-04-07 18:41:38.918 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=AddNodeToNetwork, expected=AddNodeToNetwork, cancelled=false 2015-04-07 18:41:38.919 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:41:38.920 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:41:38.920 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:41:38.921 [DEBUG] [WaveController$ZWaveSendThread:1345]- NODE 255: Response processed after 72ms/365ms. 2015-04-07 18:41:38.937 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:138 ]- NODE 4: Serializing from file etc\zwave\node4.xml 2015-04-07 18:41:38.939 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:141 ]- NODE 4: Error serializing from file: file does not exist. 2015-04-07 18:41:38.941 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 4: Node advancer - EMPTYNODE: queue length(0), free to send(true) 2015-04-07 18:41:38.941 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 4: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false) 2015-04-07 18:41:38.942 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:338 ]- NODE 4: Node advancer: Initialisation starting 2015-04-07 18:41:38.943 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:855 ]- NODE 4: Node advancer - advancing to PROTOINFO 2015-04-07 18:41:38.944 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 4: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true) 2015-04-07 18:41:38.945 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:347 ]- NODE 4: Node advancer: PROTOINFO - send IdentifyNode 2015-04-07 18:41:38.946 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = IdentifyNode (0x41), type = Request (0x00) 2015-04-07 18:41:38.947 [DEBUG] [b.z.i.protocol.ZWaveController:659 ]- Enqueueing message. Queue length = 1 2015-04-07 18:41:38.948 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240 ]- NODE 4: Node advancer - queued packet. Queue length is 1 2015-04-07 18:41:38.949 [DEBUG] [b.z.i.protocol.ZWaveController:624 ]- NODE 4: Init node thread finished 2015-04-07 18:41:38.951 [DEBUG] [WaveController$ZWaveSendThread:1229]- Took message from queue for sending. Queue length = 0 2015-04-07 18:41:38.952 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 00 41 04 BE 2015-04-07 18:41:38.953 [DEBUG] [WaveController$ZWaveSendThread:1286]- NODE 255: Sending REQUEST Message = 01 04 00 41 04 BE 2015-04-07 18:41:38.959 [DEBUG] [eController$ZWaveReceiveThread:1499]- Receive Message = 01 09 01 41 53 9C 00 04 A1 07 DB 2015-04-07 18:41:38.962 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:41:38.962 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:41:38.964 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 09 01 41 53 9C 00 04 A1 07 DB 2015-04-07 18:41:38.965 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- Process Message = 01 09 01 41 53 9C 00 04 A1 07 DB 2015-04-07 18:41:38.966 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- Message: class = IdentifyNode (0x41), type = Response (0x01), payload = 53 9C 00 04 A1 07 2015-04-07 18:41:38.967 [DEBUG] [i.p.s.IdentifyNodeMessageClass:52 ]- NODE 4: ProtocolInfo 2015-04-07 18:41:38.968 [DEBUG] [i.p.s.IdentifyNodeMessageClass:61 ]- NODE 4: Listening = false 2015-04-07 18:41:38.968 [DEBUG] [i.p.s.IdentifyNodeMessageClass:62 ]- NODE 4: Routing = true 2015-04-07 18:41:38.969 [DEBUG] [i.p.s.IdentifyNodeMessageClass:63 ]- NODE 4: Version = 4 2015-04-07 18:41:38.970 [DEBUG] [i.p.s.IdentifyNodeMessageClass:64 ]- NODE 4: FLIRS = false 2015-04-07 18:41:38.970 [DEBUG] [i.p.s.IdentifyNodeMessageClass:76 ]- NODE 4: Basic = Routing Slave 2015-04-07 18:41:38.971 [DEBUG] [i.p.s.IdentifyNodeMessageClass:83 ]- NODE 4: Generic = Alarm Sensor 2015-04-07 18:41:38.972 [DEBUG] [i.p.s.IdentifyNodeMessageClass:90 ]- NODE 4: Specific = Routing Smoke Sensor 2015-04-07 18:41:38.972 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:224 ]- NODE 4: Creating new instance of command class NO_OPERATION 2015-04-07 18:41:38.973 [DEBUG] [.z.internal.protocol.ZWaveNode:518 ]- NODE 4: Adding command class NO_OPERATION to the list of supported command classes. 2015-04-07 18:41:38.974 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:224 ]- NODE 4: Creating new instance of command class BASIC 2015-04-07 18:41:38.974 [DEBUG] [.z.internal.protocol.ZWaveNode:518 ]- NODE 4: Adding command class BASIC to the list of supported command classes. 2015-04-07 18:41:38.975 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:224 ]- NODE 4: Creating new instance of command class SENSOR_ALARM 2015-04-07 18:41:38.976 [DEBUG] [.z.internal.protocol.ZWaveNode:518 ]- NODE 4: Adding command class SENSOR_ALARM to the list of supported command classes. 2015-04-07 18:41:38.976 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:224 ]- NODE 4: Creating new instance of command class MANUFACTURER_SPECIFIC 2015-04-07 18:41:38.977 [DEBUG] [.z.internal.protocol.ZWaveNode:518 ]- NODE 4: Adding command class MANUFACTURER_SPECIFIC to the list of supported command classes. 2015-04-07 18:41:38.978 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:224 ]- NODE 4: Creating new instance of command class BATTERY 2015-04-07 18:41:38.978 [DEBUG] [.z.internal.protocol.ZWaveNode:518 ]- NODE 4: Adding command class BATTERY to the list of supported command classes. 2015-04-07 18:41:38.979 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:224 ]- NODE 4: Creating new instance of command class ASSOCIATION 2015-04-07 18:41:38.980 [DEBUG] [.z.internal.protocol.ZWaveNode:518 ]- NODE 4: Adding command class ASSOCIATION to the list of supported command classes. 2015-04-07 18:41:38.980 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:224 ]- NODE 4: Creating new instance of command class VERSION 2015-04-07 18:41:38.981 [DEBUG] [.z.internal.protocol.ZWaveNode:518 ]- NODE 4: Adding command class VERSION to the list of supported command classes. 2015-04-07 18:41:38.982 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = IdentifyNode (0x41), type = Request (0x00), payload = 04 2015-04-07 18:41:38.983 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- Recv message Message: class = IdentifyNode (0x41), type = Response (0x01), payload = 53 9C 00 04 A1 07 2015-04-07 18:41:38.983 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=IdentifyNode, expected=IdentifyNode, cancelled=false 2015-04-07 18:41:38.984 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:41:38.984 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:41:38.985 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:41:38.985 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1000]- NODE 4: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true) 2015-04-07 18:41:38.986 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:201 ]- NODE 4: Node advancer - checking initialisation queue. Queue size 1. 2015-04-07 18:41:38.987 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ]- NODE 4: Node advancer - message removed from queue. Queue size 0. 2015-04-07 18:41:38.987 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 4: Node advancer - PROTOINFO: queue length(0), free to send(true) 2015-04-07 18:41:38.989 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 4: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false) 2015-04-07 18:41:38.990 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:855 ]- NODE 4: Node advancer - advancing to NEIGHBORS 2015-04-07 18:41:38.991 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 4: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true) 2015-04-07 18:41:38.991 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:357 ]- NODE 4: Node advancer: NEIGHBORS - send RoutingInfo 2015-04-07 18:41:38.992 [DEBUG] [p.s.GetRoutingInfoMessageClass:29 ]- NODE 4: Request routing info 2015-04-07 18:41:38.993 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetRoutingInfo (0x80), type = Request (0x00) 2015-04-07 18:41:38.994 [DEBUG] [b.z.i.protocol.ZWaveController:659 ]- Enqueueing message. Queue length = 1 2015-04-07 18:41:38.995 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240 ]- NODE 4: Node advancer - queued packet. Queue length is 1 2015-04-07 18:41:38.995 [DEBUG] [WaveController$ZWaveSendThread:1345]- NODE 255: Response processed after 41ms/365ms. 2015-04-07 18:41:38.996 [DEBUG] [WaveController$ZWaveSendThread:1229]- Took message from queue for sending. Queue length = 0 2015-04-07 18:41:38.997 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 07 00 80 04 00 00 03 7F 2015-04-07 18:41:38.998 [DEBUG] [WaveController$ZWaveSendThread:1286]- NODE 255: Sending REQUEST Message = 01 07 00 80 04 00 00 03 7F 2015-04-07 18:41:39.010 [DEBUG] [eController$ZWaveReceiveThread:1499]- 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 2015-04-07 18:41:39.015 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:41:39.015 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:41:39.017 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- 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 2015-04-07 18:41:39.019 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- 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 2015-04-07 18:41:39.021 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- 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 2015-04-07 18:41:39.021 [DEBUG] [p.s.GetRoutingInfoMessageClass:47 ]- NODE 4: Got NodeRoutingInfo request. 2015-04-07 18:41:39.022 [DEBUG] [p.s.GetRoutingInfoMessageClass:78 ]- NODE 4: Neighbor nodes: 1 2015-04-07 18:41:39.023 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveNetworkEvent 2015-04-07 18:41:39.023 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:41:39.024 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 04 00 00 03 2015-04-07 18:41:39.026 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- 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 2015-04-07 18:41:39.026 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=GetRoutingInfo, expected=GetRoutingInfo, cancelled=false 2015-04-07 18:41:39.026 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:41:39.027 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:41:39.028 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:41:39.028 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1000]- NODE 4: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true) 2015-04-07 18:41:39.029 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:201 ]- NODE 4: Node advancer - checking initialisation queue. Queue size 1. 2015-04-07 18:41:39.029 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ]- NODE 4: Node advancer - message removed from queue. Queue size 0. 2015-04-07 18:41:39.030 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 4: Node advancer - NEIGHBORS: queue length(0), free to send(true) 2015-04-07 18:41:39.030 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 4: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false) 2015-04-07 18:41:39.031 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:855 ]- NODE 4: Node advancer - advancing to FAILED_CHECK 2015-04-07 18:41:39.031 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 4: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true) 2015-04-07 18:41:39.032 [DEBUG] [i.p.s.IsFailedNodeMessageClass:31 ]- NODE 4: Requesting IsFailedNode status from controller. 2015-04-07 18:41:39.034 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = IsFailedNodeID (0x62), type = Request (0x00) 2015-04-07 18:41:39.034 [DEBUG] [b.z.i.protocol.ZWaveController:659 ]- Enqueueing message. Queue length = 1 2015-04-07 18:41:39.035 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240 ]- NODE 4: Node advancer - queued packet. Queue length is 1 2015-04-07 18:41:39.036 [DEBUG] [WaveController$ZWaveSendThread:1345]- NODE 255: Response processed after 36ms/365ms. 2015-04-07 18:41:39.036 [DEBUG] [WaveController$ZWaveSendThread:1229]- Took message from queue for sending. Queue length = 0 2015-04-07 18:41:39.037 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 00 62 04 9D 2015-04-07 18:41:39.037 [DEBUG] [WaveController$ZWaveSendThread:1286]- NODE 255: Sending REQUEST Message = 01 04 00 62 04 9D 2015-04-07 18:41:39.041 [DEBUG] [eController$ZWaveReceiveThread:1499]- Receive Message = 01 04 01 62 00 98 2015-04-07 18:41:39.044 [DEBUG] [eController$ZWaveReceiveThread:1423]- Receive queue ADD: Length=1 2015-04-07 18:41:39.044 [DEBUG] [b.z.i.protocol.ZWaveController:1181]- Receive queue TAKE: Length=0 2015-04-07 18:41:39.045 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 62 00 98 2015-04-07 18:41:39.045 [DEBUG] [b.z.i.protocol.ZWaveController:1182]- Process Message = 01 04 01 62 00 98 2015-04-07 18:41:39.046 [DEBUG] [b.z.i.protocol.ZWaveController:191 ]- Message: class = IsFailedNodeID (0x62), type = Response (0x01), payload = 00 2015-04-07 18:41:39.047 [DEBUG] [i.p.s.IsFailedNodeMessageClass:54 ]- NODE 4: Is currently marked as healthy by the controller 2015-04-07 18:41:39.047 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63 ]- Sent message Message: class = IsFailedNodeID (0x62), type = Request (0x00), payload = 04 2015-04-07 18:41:39.048 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64 ]- Recv message Message: class = IsFailedNodeID (0x62), type = Response (0x01), payload = 00 2015-04-07 18:41:39.048 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65 ]- Checking transaction complete: class=IsFailedNodeID, expected=IsFailedNodeID, cancelled=false 2015-04-07 18:41:39.049 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68 ]- transaction complete! 2015-04-07 18:41:39.049 [DEBUG] [b.z.i.protocol.ZWaveController:674 ]- Notifying event listeners: ZWaveTransactionCompletedEvent 2015-04-07 18:41:39.049 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent 2015-04-07 18:41:39.050 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1000]- NODE 4: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true) 2015-04-07 18:41:39.051 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:201 ]- NODE 4: Node advancer - checking initialisation queue. Queue size 1. 2015-04-07 18:41:39.051 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ]- NODE 4: Node advancer - message removed from queue. Queue size 0. 2015-04-07 18:41:39.052 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 4: Node advancer - FAILED_CHECK: queue length(0), free to send(true) 2015-04-07 18:41:39.052 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 4: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false) 2015-04-07 18:41:39.052 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:855 ]- NODE 4: Node advancer - advancing to WAIT 2015-04-07 18:41:39.053 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 4: Node advancer: loop - WAIT try 0: stageAdvanced(true) 2015-04-07 18:41:39.053 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:380 ]- NODE 4: Node advancer: WAIT - Listening=false, FrequentlyListening=false 2015-04-07 18:41:39.054 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:398 ]- NODE 4: Node advancer: WAIT - Still waiting! 2015-04-07 18:41:39.055 [DEBUG] [WaveController$ZWaveSendThread:1345]- NODE 255: Response processed after 17ms/365ms. 2015-04-07 18:42:10.158 [DEBUG] [.z.i.config.ZWaveConfiguration:929 ]- NODE 4: Heal node 2015-04-07 18:42:10.161 [DEBUG] [z.internal.ZWaveNetworkMonitor:267 ]- NODE 4: Starting heal 2015-04-07 18:42:56.304 [DEBUG] [z.internal.ZWaveNetworkMonitor:353 ]- Network Monitor: No nodes to ping!

teichsta commented 9 years ago

Hi @ComJack this seems to be technical question which should be discussed on the Google Group (see https://groups.google.com/forum/#!forum/openhab) before. Once an issue is detected feel free to open an entry here. Thanks, Thomas E.-E.