How-to Article on MakeUseOf

Branden_Smale · September 23, 2015, 3:04am

I figured how to view. Cant attach the log so I will quote it. All I can see it looks good, but still doesnt show up in Habmin2

2015-09-22 21:11:11.371 [DEBUG] [.zwave.internal.ZWaveActivator:36  ]- Z-Wave binding started. Version 1.7.1
2015-09-22 21:11:11.588 [DEBUG] [.z.internal.ZWaveActiveBinding:175 ]- ConverterHandler not initialised. Polling disabled.
2015-09-22 21:11:11.616 [INFO ] [.z.internal.ZWaveActiveBinding:325 ]- Update config, port = /dev/ttyACM0
2015-09-22 21:11:11.618 [INFO ] [.z.internal.ZWaveActiveBinding:330 ]- Update config, healtime = 2
2015-09-22 21:11:11.631 [INFO ] [.z.internal.ZWaveActiveBinding:384 ]- Update config, softReset = false
2015-09-22 21:11:11.633 [INFO ] [.z.internal.ZWaveActiveBinding:393 ]- Update config, masterController = true
2015-09-22 21:11:11.634 [DEBUG] [.z.internal.ZWaveActiveBinding:282 ]- Initialising zwave binding
2015-09-22 21:11:11.761 [INFO ] [b.z.i.protocol.ZWaveController:146 ]- Starting Z-Wave controller
2015-09-22 21:11:11.763 [INFO ] [b.z.i.protocol.ZWaveController:154 ]- Z-Wave timeout is set to 5000ms. Soft reset is false.
2015-09-22 21:11:11.765 [INFO ] [b.z.i.protocol.ZWaveController:407 ]- Connecting to serial port /dev/ttyACM0
2015-09-22 21:11:11.923 [DEBUG] [eController$ZWaveReceiveThread:1460]- Starting Z-Wave thread: Receive
2015-09-22 21:11:12.064 [DEBUG] [WaveController$ZWaveSendThread:1244]- Starting Z-Wave thread: Send
2015-09-22 21:11:12.067 [INFO ] [b.z.i.protocol.ZWaveController:427 ]- Serial port is initialized
2015-09-22 21:11:12.067 [DEBUG] [b.z.i.protocol.ZWaveController:1201]- Starting Z-Wave thread: Input
2015-09-22 21:11:15.091 [DEBUG] [veController$WatchDogTimerTask:176 ]- Initialising network
2015-09-22 21:11:15.121 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetVersion (0x15), type = Request (0x00)
2015-09-22 21:11:15.124 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 1
2015-09-22 21:11:15.124 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-09-22 21:11:15.128 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = MemoryGetId (0x20), type = Request (0x00)
2015-09-22 21:11:15.129 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 1
2015-09-22 21:11:15.132 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 15 E9 
2015-09-22 21:11:15.135 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiGetCapabilities (0x07), type = Request (0x00)
2015-09-22 21:11:15.135 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 15 E9 
2015-09-22 21:11:15.136 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 2
2015-09-22 21:11:15.142 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiSetTimeouts (0x06), type = Request (0x00)
2015-09-22 21:11:15.144 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 3
2015-09-22 21:11:15.147 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 10 01 15 5A 2D 57 61 76 65 20 33 2E 39 35 00 01 99 
2015-09-22 21:11:15.147 [DEBUG] [i.p.s.GetSucNodeIdMessageClass:30  ]- Get SUC NodeID
2015-09-22 21:11:15.150 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetSucNodeId (0x56), type = Request (0x00)
2015-09-22 21:11:15.152 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 4
2015-09-22 21:11:15.158 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:11:15.164 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 10 01 15 5A 2D 57 61 76 65 20 33 2E 39 35 00 01 99 
2015-09-22 21:11:15.169 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 10 01 15 5A 2D 57 61 76 65 20 33 2E 39 35 00 01 99 
2015-09-22 21:11:15.173 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=0
2015-09-22 21:11:15.176 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = GetVersion (0x15), type = Response (0x01), payload = 5A 2D 57 61 76 65 20 33 2E 39 35 00 01 
2015-09-22 21:11:15.214 [DEBUG] [z.i.p.s.GetVersionMessageClass:39  ]- Got MessageGetVersion response. Version = Z-Wave 3.95, Library Type = 0x01
2015-09-22 21:11:15.216 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = GetVersion (0x15), type = Request (0x00), payload = 
2015-09-22 21:11:15.220 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = GetVersion (0x15), type = Response (0x01), payload = 5A 2D 57 61 76 65 20 33 2E 39 35 00 01 
2015-09-22 21:11:15.221 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=GetVersion, expected=GetVersion, cancelled=false
2015-09-22 21:11:15.223 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2015-09-22 21:11:15.224 [DEBUG] [b.z.i.protocol.ZWaveController:682 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2015-09-22 21:11:15.227 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2015-09-22 21:11:15.238 [DEBUG] [WaveController$ZWaveSendThread:1374]- NODE 255: Response processed after 100ms/100ms.
2015-09-22 21:11:15.239 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 3
2015-09-22 21:11:15.241 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 20 DC 
2015-09-22 21:11:15.244 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 20 DC 
2015-09-22 21:11:15.249 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 08 01 20 C6 FB 34 1E 01 C0 
2015-09-22 21:11:15.254 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=1
2015-09-22 21:11:15.256 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:11:15.259 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 08 01 20 C6 FB 34 1E 01 C0 
2015-09-22 21:11:15.261 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 08 01 20 C6 FB 34 1E 01 C0 
2015-09-22 21:11:15.264 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = MemoryGetId (0x20), type = Response (0x01), payload = C6 FB 34 1E 01 
2015-09-22 21:11:15.266 [DEBUG] [.i.p.s.MemoryGetIdMessageClass:41  ]- Got MessageMemoryGetId response. Home id = 0xC6FB341E, Controller Node id = 1
2015-09-22 21:11:15.268 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = MemoryGetId (0x20), type = Request (0x00), payload = 
2015-09-22 21:11:15.270 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = MemoryGetId (0x20), type = Response (0x01), payload = C6 FB 34 1E 01 
2015-09-22 21:11:15.271 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=MemoryGetId, expected=MemoryGetId, cancelled=false
2015-09-22 21:11:15.273 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2015-09-22 21:11:15.274 [DEBUG] [b.z.i.protocol.ZWaveController:682 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2015-09-22 21:11:15.275 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2015-09-22 21:11:15.276 [DEBUG] [WaveController$ZWaveSendThread:1374]- NODE 255: Response processed after 31ms/100ms.
2015-09-22 21:11:15.277 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 2
2015-09-22 21:11:15.280 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 07 FB 
2015-09-22 21:11:15.284 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 07 FB 
2015-09-22 21:11:15.298 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 2B 01 07 01 00 00 86 01 01 00 5A FE 81 FF 88 4F 1F 00 00 FB 9F 7D A0 67 00 00 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 60 00 00 FA 
2015-09-22 21:11:15.316 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:11:15.327 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 2B 01 07 01 00 00 86 01 01 00 5A FE 81 FF 88 4F 1F 00 00 FB 9F 7D A0 67 00 00 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 60 00 00 FA 
2015-09-22 21:11:15.332 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=0
2015-09-22 21:11:15.340 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 2B 01 07 01 00 00 86 01 01 00 5A FE 81 FF 88 4F 1F 00 00 FB 9F 7D A0 67 00 00 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 60 00 00 FA 
2015-09-22 21:11:15.349 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = SerialApiGetCapabilities (0x07), type = Response (0x01), payload = 01 00 00 86 01 01 00 5A FE 81 FF 88 4F 1F 00 00 FB 9F 7D A0 67 00 00 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 60 00 00 
2015-09-22 21:11:15.351 [DEBUG] [ApiGetCapabilitiesMessageClass:45  ]- API Version = 1.0
2015-09-22 21:11:15.353 [DEBUG] [ApiGetCapabilitiesMessageClass:46  ]- Manufacture ID = 0x86
2015-09-22 21:11:15.354 [DEBUG] [ApiGetCapabilitiesMessageClass:47  ]- Device Type = 0x101
2015-09-22 21:11:15.356 [DEBUG] [ApiGetCapabilitiesMessageClass:48  ]- Device ID = 0x5a
2015-09-22 21:11:15.357 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SerialApiGetInitData
2015-09-22 21:11:15.358 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SerialApiApplicationNodeInfo
2015-09-22 21:11:15.359 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: ApplicationCommandHandler
2015-09-22 21:11:15.360 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: GetControllerCapabilities
2015-09-22 21:11:15.362 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SerialApiSetTimeouts
2015-09-22 21:11:15.363 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SerialApiGetCapabilities
2015-09-22 21:11:15.364 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SerialApiSoftReset
2015-09-22 21:11:15.366 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x09
2015-09-22 21:11:15.367 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: RfReceiveMode
2015-09-22 21:11:15.368 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SetSleepMode
2015-09-22 21:11:15.369 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SendNodeInfo
2015-09-22 21:11:15.370 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SendData
2015-09-22 21:11:15.371 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SendDataMulti
2015-09-22 21:11:15.373 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: GetVersion
2015-09-22 21:11:15.374 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SendDataAbort
2015-09-22 21:11:15.375 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: RfPowerLevelSet
2015-09-22 21:11:15.376 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SendDataMeta
2015-09-22 21:11:15.377 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: GetRandom
2015-09-22 21:11:15.378 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: MemoryGetId
2015-09-22 21:11:15.379 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: MemoryGetByte
2015-09-22 21:11:15.380 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: MemoryPutByte
2015-09-22 21:11:15.382 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: ReadMemory
2015-09-22 21:11:15.383 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: WriteMemory
2015-09-22 21:11:15.384 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x27
2015-09-22 21:11:15.385 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x29
2015-09-22 21:11:15.386 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x2a
2015-09-22 21:11:15.388 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x2b
2015-09-22 21:11:15.389 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x2c
2015-09-22 21:11:15.391 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x2d
2015-09-22 21:11:15.392 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: IdentifyNode
2015-09-22 21:11:15.393 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SetDefault
2015-09-22 21:11:15.394 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: ReplicationCommandComplete
2015-09-22 21:11:15.396 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: ReplicationSendData
2015-09-22 21:11:15.397 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: AssignReturnRoute
2015-09-22 21:11:15.398 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: DeleteReturnRoute
2015-09-22 21:11:15.399 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: RequestNodeNeighborUpdate
2015-09-22 21:11:15.400 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: ApplicationUpdate
2015-09-22 21:11:15.401 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: AddNodeToNetwork
2015-09-22 21:11:15.403 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: RemoveNodeFromNetwork
2015-09-22 21:11:15.404 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: CreateNewPrimary
2015-09-22 21:11:15.405 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: ControllerChange
2015-09-22 21:11:15.406 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SetLearnMode
2015-09-22 21:11:15.407 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: AssignSucReturnRoute
2015-09-22 21:11:15.407 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: RequestNetworkUpdate
2015-09-22 21:11:15.408 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SetSucNodeID
2015-09-22 21:11:15.409 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: DeleteSUCReturnRoute
2015-09-22 21:11:15.410 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: GetSucNodeId
2015-09-22 21:11:15.411 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SendSucId
2015-09-22 21:11:15.413 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x5e
2015-09-22 21:11:15.414 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: RequestNodeInfo
2015-09-22 21:11:15.415 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: RemoveFailedNodeID
2015-09-22 21:11:15.416 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: IsFailedNodeID
2015-09-22 21:11:15.417 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: ReplaceFailedNode
2015-09-22 21:11:15.418 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x66
2015-09-22 21:11:15.420 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x67
2015-09-22 21:11:15.421 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: GetRoutingInfo
2015-09-22 21:11:15.422 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: LockRoute
2015-09-22 21:11:15.423 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x92
2015-09-22 21:11:15.424 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x93
2015-09-22 21:11:15.425 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0x98
2015-09-22 21:11:15.427 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xb4
2015-09-22 21:11:15.428 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: WatchDogKick
2015-09-22 21:11:15.429 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: WatchDogDisable
2015-09-22 21:11:15.430 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xb8
2015-09-22 21:11:15.432 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xb9
2015-09-22 21:11:15.433 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: RfPowerLevelSet
2015-09-22 21:11:15.434 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: GetLibraryType
2015-09-22 21:11:15.435 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: SendTestFrame
2015-09-22 21:11:15.436 [DEBUG] [ApiGetCapabilitiesMessageClass:59  ]- Supports: GetProtocolStatus
2015-09-22 21:11:15.437 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xd2
2015-09-22 21:11:15.438 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xd3
2015-09-22 21:11:15.440 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xd4
2015-09-22 21:11:15.441 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xee
2015-09-22 21:11:15.442 [DEBUG] [ApiGetCapabilitiesMessageClass:56  ]- Supports: Unknown Class 0xef
2015-09-22 21:11:15.444 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SerialApiGetCapabilities (0x07), type = Request (0x00), payload = 
2015-09-22 21:11:15.452 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = SerialApiGetCapabilities (0x07), type = Response (0x01), payload = 01 00 00 86 01 01 00 5A FE 81 FF 88 4F 1F 00 00 FB 9F 7D A0 67 00 00 80 00 80 86 00 00 00 E8 73 00 00 0E 00 00 60 00 00 
2015-09-22 21:11:15.453 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=SerialApiGetCapabilities, expected=SerialApiGetCapabilities, cancelled=false
2015-09-22 21:11:15.454 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2015-09-22 21:11:15.456 [DEBUG] [b.z.i.protocol.ZWaveController:682 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2015-09-22 21:11:15.457 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2015-09-22 21:11:15.458 [DEBUG] [WaveController$ZWaveSendThread:1374]- NODE 255: Response processed after 172ms/172ms.
2015-09-22 21:11:15.461 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = SerialApiGetInitData (0x02), type = Request (0x00)
2015-09-22 21:11:15.462 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 3
2015-09-22 21:11:15.464 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 2
2015-09-22 21:11:15.467 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 05 00 06 96 0F 65 
2015-09-22 21:11:15.470 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 05 00 06 96 0F 65 
2015-09-22 21:11:15.475 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 05 01 06 96 0F 64 
2015-09-22 21:11:15.479 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=1
2015-09-22 21:11:15.480 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:11:15.484 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 05 01 06 96 0F 64 
2015-09-22 21:11:15.486 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 05 01 06 96 0F 64 
2015-09-22 21:11:15.487 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = SerialApiSetTimeouts (0x06), type = Response (0x01), payload = 96 0F 
2015-09-22 21:11:15.489 [DEBUG] [rialApiSetTimeoutsMessageClass:40  ]- Got SerialApiSetTimeouts response. ACK=150, BYTE=15
2015-09-22 21:11:15.491 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SerialApiSetTimeouts (0x06), type = Request (0x00), payload = 96 0F 
2015-09-22 21:11:15.493 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = SerialApiSetTimeouts (0x06), type = Response (0x01), payload = 96 0F 
2015-09-22 21:11:15.494 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=SerialApiSetTimeouts, expected=SerialApiSetTimeouts, cancelled=false
2015-09-22 21:11:15.495 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2015-09-22 21:11:15.496 [DEBUG] [b.z.i.protocol.ZWaveController:682 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2015-09-22 21:11:15.496 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2015-09-22 21:11:15.497 [DEBUG] [WaveController$ZWaveSendThread:1374]- NODE 255: Response processed after 26ms/172ms.
2015-09-22 21:11:15.499 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 1
2015-09-22 21:11:15.501 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 56 AA 
2015-09-22 21:11:15.503 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 56 AA 
2015-09-22 21:11:15.508 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 04 01 56 00 AC 
2015-09-22 21:11:15.511 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=1
2015-09-22 21:11:15.512 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:11:15.515 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 56 00 AC 
2015-09-22 21:11:15.518 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 04 01 56 00 AC 
2015-09-22 21:11:15.520 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = GetSucNodeId (0x56), type = Response (0x01), payload = 00 
2015-09-22 21:11:15.521 [DEBUG] [i.p.s.GetSucNodeIdMessageClass:41  ]- Got SUC NodeID response.
2015-09-22 21:11:15.523 [DEBUG] [i.p.s.GetSucNodeIdMessageClass:47  ]- No SUC Node is set
2015-09-22 21:11:15.525 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = GetSucNodeId (0x56), type = Request (0x00), payload = 
2015-09-22 21:11:15.527 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = GetSucNodeId (0x56), type = Response (0x01), payload = 00 
2015-09-22 21:11:15.528 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=GetSucNodeId, expected=GetSucNodeId, cancelled=false
2015-09-22 21:11:15.530 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2015-09-22 21:11:15.531 [DEBUG] [b.z.i.protocol.ZWaveController:682 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2015-09-22 21:11:15.532 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2015-09-22 21:11:15.533 [DEBUG] [WaveController$ZWaveSendThread:1374]- NODE 255: Response processed after 28ms/172ms.
2015-09-22 21:11:15.535 [DEBUG] [rollerCapabilitiesMessageClass:41  ]- Creating GET_CONTROLLER_CAPABILITIES message
2015-09-22 21:11:15.537 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = GetControllerCapabilities (0x05), type = Request (0x00)
2015-09-22 21:11:15.538 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 2
2015-09-22 21:11:15.539 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 1
2015-09-22 21:11:15.543 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 02 FE 
2015-09-22 21:11:15.546 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 02 FE 
2015-09-22 21:11:15.650 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 25 01 02 05 00 1D 03 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 05 00 C7 
2015-09-22 21:11:15.668 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:11:15.674 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 25 01 02 05 00 1D 03 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 05 00 C7 
2015-09-22 21:11:15.680 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 25 01 02 05 00 1D 03 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 05 00 C7 
2015-09-22 21:11:15.682 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=0
2015-09-22 21:11:15.688 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = SerialApiGetInitData (0x02), type = Response (0x01), payload = 05 00 1D 03 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 05 00 
2015-09-22 21:11:15.690 [DEBUG] [rialApiGetInitDataMessageClass:39  ]- Got MessageSerialApiGetInitData response.
2015-09-22 21:11:15.691 [INFO ] [rialApiGetInitDataMessageClass:57  ]- NODE 1: Node found
2015-09-22 21:11:15.693 [INFO ] [rialApiGetInitDataMessageClass:57  ]- NODE 2: Node found
2015-09-22 21:11:15.695 [INFO ] [rialApiGetInitDataMessageClass:65  ]- ZWave Controller using Controller API
2015-09-22 21:11:15.696 [INFO ] [rialApiGetInitDataMessageClass:66  ]- ZWave Controller is Primary Controller
2015-09-22 21:11:15.697 [INFO ] [rialApiGetInitDataMessageClass:67  ]- ------------Number of Nodes Found Registered to ZWave Controller------------
2015-09-22 21:11:15.699 [INFO ] [rialApiGetInitDataMessageClass:68  ]- # Nodes = 2
2015-09-22 21:11:15.700 [INFO ] [rialApiGetInitDataMessageClass:69  ]- ----------------------------------------------------------------------------
2015-09-22 21:11:15.702 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SerialApiGetInitData (0x02), type = Request (0x00), payload = 
2015-09-22 21:11:15.709 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = SerialApiGetInitData (0x02), type = Response (0x01), payload = 05 00 1D 03 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 05 00 
2015-09-22 21:11:15.710 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=SerialApiGetInitData, expected=SerialApiGetInitData, cancelled=false
2015-09-22 21:11:15.711 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2015-09-22 21:11:15.713 [DEBUG] [b.z.i.protocol.ZWaveController:682 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2015-09-22 21:11:15.714 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2015-09-22 21:11:15.716 [DEBUG] [WaveController$ZWaveSendThread:1374]- NODE 255: Response processed after 167ms/172ms.
2015-09-22 21:11:17.285 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:138 ]- NODE 1: Serializing from file etc/zwave/node1.xml
2015-09-22 21:11:17.431 [DEBUG] [b.z.i.protocol.ZWaveController:307 ]- NODE 1: Restored from config.
2015-09-22 21:11:17.489 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 1: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2015-09-22 21:11:17.491 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1098]- NODE 1: Initialisation retry timer started 5000
2015-09-22 21:11:17.493 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 1: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2015-09-22 21:11:17.495 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:338 ]- NODE 1: Node advancer: Initialisation starting
2015-09-22 21:11:17.496 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:860 ]- NODE 1: Node advancer - advancing to PROTOINFO
2015-09-22 21:11:17.498 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 1: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2015-09-22 21:11:17.499 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:347 ]- NODE 1: Node advancer: PROTOINFO - send IdentifyNode
2015-09-22 21:11:17.503 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = IdentifyNode (0x41), type = Request (0x00)
2015-09-22 21:11:17.505 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 2
2015-09-22 21:11:17.506 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240 ]- NODE 1: Node advancer - queued packet. Queue length is 1
2015-09-22 21:11:17.550 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:138 ]- NODE 2: Serializing from file etc/zwave/node2.xml
2015-09-22 21:11:17.637 [DEBUG] [b.z.i.protocol.ZWaveController:307 ]- NODE 2: Restored from config.
2015-09-22 21:11:17.639 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 2: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2015-09-22 21:11:17.640 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1098]- NODE 2: Initialisation retry timer started 5000
2015-09-22 21:11:17.642 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 2: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2015-09-22 21:11:17.643 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:338 ]- NODE 2: Node advancer: Initialisation starting
2015-09-22 21:11:17.644 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:860 ]- NODE 2: Node advancer - advancing to PROTOINFO
2015-09-22 21:11:17.644 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 2: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2015-09-22 21:11:17.645 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:347 ]- NODE 2: Node advancer: PROTOINFO - send IdentifyNode
2015-09-22 21:11:17.646 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = IdentifyNode (0x41), type = Request (0x00)
2015-09-22 21:11:17.648 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 3
2015-09-22 21:11:17.649 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240 ]- NODE 2: Node advancer - queued packet. Queue length is 1
2015-09-22 21:11:17.650 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 2
2015-09-22 21:11:17.652 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 03 00 05 F9 
2015-09-22 21:11:17.654 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 03 00 05 F9 
2015-09-22 21:11:17.658 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 04 01 05 08 F7 
2015-09-22 21:11:17.661 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=1
2015-09-22 21:11:17.662 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:11:17.664 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 05 08 F7 
2015-09-22 21:11:17.666 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 04 01 05 08 F7 
2015-09-22 21:11:17.667 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = GetControllerCapabilities (0x05), type = Response (0x01), payload = 08 
2015-09-22 21:11:17.669 [DEBUG] [rollerCapabilitiesMessageClass:55  ]- Controller is secondary = false
2015-09-22 21:11:17.670 [DEBUG] [rollerCapabilitiesMessageClass:56  ]- Controller is on other network = false

bob_dickenson · September 23, 2015, 10:16am

The only nodes in here are the NODE 1 and NODE 255 – both belonging to the controller itself.

What other devices do you think should be there ?

Have you done the “walk around to devices, z-stick in hand, put stick in inclusion mode, pushed the button on the device you are trying to include, seen the stick light pattern change as it includes the node” .

Branden_Smale · September 23, 2015, 10:28am

There is also node 2. I could only post 32000 chatacters. Yes, it is included, and it is communicating according to the log

bob_dickenson · September 23, 2015, 11:43am

what device is Node 2 (switch of some sort, dimmer,sensor) SPECIFIC mfg and model will help.

what does your ITEMS file definition for Node 2 look like ?

Paste in some zwave log info showing Node 2 communication. (From first time NODE 2 is in z-log)

Branden_Smale · September 23, 2015, 11:50am

015-09-22 21:11:18.055 [DEBUG] [WaveController$ZWaveSendThread:1374]- NODE 255: Response processed after 233ms/233ms.
2015-09-22 21:11:18.056 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-09-22 21:11:18.060 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 07 00 80 02 00 00 03 79 
2015-09-22 21:11:18.062 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 07 00 80 02 00 00 03 79 
2015-09-22 21:11:18.072 [DEBUG] [eController$ZWaveReceiveThread:1528]- 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-09-22 21:11:18.080 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:11:18.084 [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-09-22 21:11:18.089 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- 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-09-22 21:11:18.092 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=0
2015-09-22 21:11:18.093 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- 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-09-22 21:11:18.095 [DEBUG] [p.s.GetRoutingInfoMessageClass:47  ]- NODE 2: Got NodeRoutingInfo request.
2015-09-22 21:11:18.096 [DEBUG] [p.s.GetRoutingInfoMessageClass:78  ]- NODE 2: Neighbor nodes: 1
2015-09-22 21:11:18.098 [DEBUG] [b.z.i.protocol.ZWaveController:682 ]- Notifying event listeners: ZWaveNetworkEvent
2015-09-22 21:11:18.099 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2015-09-22 21:11:18.101 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = GetRoutingInfo (0x80), type = Request (0x00), payload = 02 00 00 03 
2015-09-22 21:11:18.106 [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-09-22 21:11:18.107 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=GetRoutingInfo, expected=GetRoutingInfo, cancelled=false
2015-09-22 21:11:18.108 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2015-09-22 21:11:18.109 [DEBUG] [b.z.i.protocol.ZWaveController:682 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2015-09-22 21:11:18.111 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2015-09-22 21:11:18.112 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1005]- NODE 2: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true)
2015-09-22 21:11:18.114 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:201 ]- NODE 2: Node advancer - checking initialisation queue. Queue size 1.
2015-09-22 21:11:18.115 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ]- NODE 2: Node advancer - message removed from queue. Queue size 0.
2015-09-22 21:11:18.116 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 2: Node advancer - NEIGHBORS: queue length(0), free to send(true)
2015-09-22 21:11:18.117 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1098]- NODE 2: Initialisation retry timer started 5000
2015-09-22 21:11:18.118 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 2: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false)
2015-09-22 21:11:18.120 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:860 ]- NODE 2: Node advancer - advancing to FAILED_CHECK
2015-09-22 21:11:18.121 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 2: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true)
2015-09-22 21:11:18.124 [DEBUG] [i.p.s.IsFailedNodeMessageClass:31  ]- NODE 2: Requesting IsFailedNode status from controller.
2015-09-22 21:11:18.126 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 255: Creating empty message of class = IsFailedNodeID (0x62), type = Request (0x00)
2015-09-22 21:11:18.141 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 1
2015-09-22 21:11:18.143 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240 ]- NODE 2: Node advancer - queued packet. Queue length is 1
2015-09-22 21:11:18.145 [DEBUG] [WaveController$ZWaveSendThread:1374]- NODE 255: Response processed after 81ms/233ms.
2015-09-22 21:11:18.146 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-09-22 21:11:18.149 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 00 62 02 9B 
2015-09-22 21:11:18.151 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 255: Sending REQUEST Message = 01 04 00 62 02 9B 
2015-09-22 21:11:18.155 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 04 01 62 00 98 
2015-09-22 21:11:18.158 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:11:18.159 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 62 00 98 
2015-09-22 21:11:18.161 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 04 01 62 00 98 
2015-09-22 21:11:18.162 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = IsFailedNodeID (0x62), type = Response (0x01), payload = 00 
2015-09-22 21:11:18.163 [DEBUG] [i.p.s.IsFailedNodeMessageClass:54  ]- NODE 2: Is currently marked as healthy by the controller
2015-09-22 21:11:18.165 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = IsFailedNodeID (0x62), type = Request (0x00), payload = 02 
2015-09-22 21:11:18.166 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = IsFailedNodeID (0x62), type = Response (0x01), payload = 00 
2015-09-22 21:11:18.167 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=IsFailedNodeID, expected=IsFailedNodeID, cancelled=false
2015-09-22 21:11:18.168 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2015-09-22 21:11:18.168 [DEBUG] [b.z.i.protocol.ZWaveController:682 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2015-09-22 21:11:18.169 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2015-09-22 21:11:18.170 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1005]- NODE 2: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true)
2015-09-22 21:11:18.171 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:201 ]- NODE 2: Node advancer - checking initialisation queue. Queue size 1.
2015-09-22 21:11:18.172 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=0
2015-09-22 21:11:18.172 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ]- NODE 2: Node advancer - message removed from queue. Queue size 0.
2015-09-22 21:11:18.174 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 2: Node advancer - FAILED_CHECK: queue length(0), free to send(true)
2015-09-22 21:11:18.175 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1098]- NODE 2: Initialisation retry timer started 5000
2015-09-22 21:11:18.176 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 2: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false)
2015-09-22 21:11:18.177 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:860 ]- NODE 2: Node advancer - advancing to WAIT
2015-09-22 21:11:18.178 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 2: Node advancer: loop - WAIT try 0: stageAdvanced(true)
2015-09-22 21:11:18.179 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:380 ]- NODE 2: Node advancer: WAIT - Listening=true, FrequentlyListening=false
2015-09-22 21:11:18.180 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:384 ]- NODE 2: Node advancer: WAIT - Advancing
2015-09-22 21:11:18.181 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:860 ]- NODE 2: Node advancer - advancing to PING
2015-09-22 21:11:18.183 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 2: Node advancer: loop - PING try 0: stageAdvanced(true)
2015-09-22 21:11:18.184 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:417 ]- NODE 2: Node advancer: PING - send NoOperation
2015-09-22 21:11:18.185 [DEBUG] [c.ZWaveNoOperationCommandClass:72  ]- NODE 2: Creating new message for command No Operation
2015-09-22 21:11:18.187 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 2: Creating empty message of class = SendData (0x13), type = Request (0x00)
2015-09-22 21:11:18.188 [DEBUG] [b.z.i.protocol.ZWaveController:985 ]- Callback ID = 2
2015-09-22 21:11:18.190 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 1
2015-09-22 21:11:18.191 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240 ]- NODE 2: Node advancer - queued packet. Queue length is 1
2015-09-22 21:11:18.192 [DEBUG] [WaveController$ZWaveSendThread:1374]- NODE 255: Response processed after 39ms/233ms.
2015-09-22 21:11:18.193 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-09-22 21:11:18.195 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 08 00 13 02 01 00 25 02 C0 
2015-09-22 21:11:18.197 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 2: Sending REQUEST Message = 01 08 00 13 02 01 00 25 02 C0 
2015-09-22 21:11:18.208 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 04 01 13 01 E8 
2015-09-22 21:11:18.210 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=1
2015-09-22 21:11:18.211 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:11:18.213 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 13 01 E8 
2015-09-22 21:11:18.214 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 04 01 13 01 E8 
2015-09-22 21:11:18.215 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
2015-09-22 21:11:18.218 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 2: Sent Data successfully placed on stack.
2015-09-22 21:11:18.224 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 07 00 13 02 00 00 02 EB 
2015-09-22 21:11:18.227 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=1
2015-09-22 21:11:18.228 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:11:18.230 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 09 00 13 02 00 00 02 00 00 E5 
2015-09-22 21:11:18.231 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 09 00 13 02 00 00 02 00 00 E5 
2015-09-22 21:11:18.233 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = SendData (0x13), type = Request (0x00), payload = 02 00 00 02 
2015-09-22 21:11:18.238 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 2: SendData Request. CallBack ID = 2, Status = Transmission complete and ACK received(0)
2015-09-22 21:11:18.241 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 02 01 00 
2015-09-22 21:11:18.242 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 02 00 00 02 
2015-09-22 21:11:18.243 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=SendData, expected=SendData, cancelled=false
2015-09-22 21:11:18.244 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2015-09-22 21:11:18.245 [DEBUG] [b.z.i.protocol.ZWaveController:682 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2015-09-22 21:11:18.246 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2015-09-22 21:11:18.246 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1005]- NODE 2: Node advancer - PING: Transaction complete (SendData:Request) success(true)
2015-09-22 21:11:18.247 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:201 ]- NODE 2: Node advancer - checking initialisation queue. Queue size 1.
2015-09-22 21:11:18.248 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ]- NODE 2: Node advancer - message removed from queue. Queue size 0.
2015-09-22 21:11:18.249 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 2: Node advancer - PING: queue length(0), free to send(true)
2015-09-22 21:11:18.250 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1098]- NODE 2: Initialisation retry timer started 5000
2015-09-22 21:11:18.251 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 2: Node advancer: loop - PING try 1: stageAdvanced(false)
2015-09-22 21:11:18.253 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:860 ]- NODE 2: Node advancer - advancing to DETAILS
2015-09-22 21:11:18.254 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 2: Node advancer: loop - DETAILS try 0: stageAdvanced(true)
2015-09-22 21:11:18.256 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:435 ]- NODE 2: Node advancer: Restored from file - skipping static initialisation
2015-09-22 21:11:18.257 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:860 ]- NODE 2: Node advancer - advancing to DYNAMIC_VALUES
2015-09-22 21:11:18.258 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 2: Node advancer: loop - DYNAMIC_VALUES try 0: stageAdvanced(true)
2015-09-22 21:11:18.260 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:773 ]- NODE 2: Node advancer: DYNAMIC_VALUES - checking MANUFACTURER_SPECIFIC
2015-09-22 21:11:18.261 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:773 ]- NODE 2: Node advancer: DYNAMIC_VALUES - checking BASIC
2015-09-22 21:11:18.262 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:773 ]- NODE 2: Node advancer: DYNAMIC_VALUES - checking SWITCH_MULTILEVEL
2015-09-22 21:11:18.263 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:776 ]- NODE 2: Node advancer: DYNAMIC_VALUES - found    SWITCH_MULTILEVEL
2015-09-22 21:11:18.265 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:780 ]- NODE 2: Found 1 instances of SWITCH_MULTILEVEL
2015-09-22 21:11:18.266 [DEBUG] [veMultiLevelSwitchCommandClass:138 ]- NODE 2: Creating new message for command SWITCH_MULTILEVEL_GET
2015-09-22 21:11:18.268 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 2: Creating empty message of class = SendData (0x13), type = Request (0x00)
2015-09-22 21:11:18.269 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:773 ]- NODE 2: Node advancer: DYNAMIC_VALUES - checking SCENE_ACTIVATION
2015-09-22 21:11:18.271 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:773 ]- NODE 2: Node advancer: DYNAMIC_VALUES - checking VERSION
2015-09-22 21:11:18.272 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:773 ]- NODE 2: Node advancer: DYNAMIC_VALUES - checking APPLICATION_STATUS
2015-09-22 21:11:18.273 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:773 ]- NODE 2: Node advancer: DYNAMIC_VALUES - checking NO_OPERATION
2015-09-22 21:11:18.274 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:808 ]- NODE 2: Node advancer: DYNAMIC_VALUES - queued 1 frames
2015-09-22 21:11:18.276 [DEBUG] [b.z.i.protocol.ZWaveController:985 ]- Callback ID = 3
2015-09-22 21:11:18.277 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 1
2015-09-22 21:11:18.278 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:240 ]- NODE 2: Node advancer - queued packet. Queue length is 1
2015-09-22 21:11:18.280 [DEBUG] [WaveController$ZWaveSendThread:1374]- NODE 2: Response processed after 81ms/233ms.
2015-09-22 21:11:18.281 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-09-22 21:11:18.283 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 09 00 13 02 02 26 02 25 03 E7 
2015-09-22 21:11:18.285 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 2: Sending REQUEST Message = 01 09 00 13 02 02 26 02 25 03 E7 
2015-09-22 21:11:18.294 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 04 01 13 01 E8 
2015-09-22 21:11:18.297 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=1
2015-09-22 21:11:18.298 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:11:18.300 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 13 01 E8 
2015-09-22 21:11:18.301 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 04 01 13 01 E8 
2015-09-22 21:11:18.303 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
2015-09-22 21:11:18.305 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 2: Sent Data successfully placed on stack.
2015-09-22 21:11:18.313 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 07 00 13 03 00 00 03 EB 
2015-09-22 21:11:18.315 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=1
2015-09-22 21:11:18.317 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:11:18.319 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 09 00 13 03 00 00 03 00 00 E5 
2015-09-22 21:11:18.320 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 09 00 13 03 00 00 03 00 00 E5 
2015-09-22 21:11:18.322 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = SendData (0x13), type = Request (0x00), payload = 03 00 00 03 
2015-09-22 21:11:18.324 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 2: SendData Request. CallBack ID = 3, Status = Transmission complete and ACK received(0)
2015-09-22 21:11:18.326 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 02 02 26 02 
2015-09-22 21:11:18.327 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 03 00 00 03 
2015-09-22 21:11:18.329 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=SendData, expected=ApplicationCommandHandler, cancelled=false
2015-09-22 21:11:18.331 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 09 00 04 00 02 03 26 03 00 D6 
2015-09-22 21:11:18.334 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=1
2015-09-22 21:11:18.336 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:11:18.337 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 09 00 04 00 02 03 26 03 00 D6 
2015-09-22 21:11:18.339 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 09 00 04 00 02 03 26 03 00 D6 
2015-09-22 21:11:18.340 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 02 03 26 03 00 
2015-09-22 21:11:18.344 [DEBUG] [ApplicationCommandMessageClass:38  ]- NODE 2: Application Command Request (ALIVE:DYNAMIC_VALUES)
2015-09-22 21:11:18.345 [DEBUG] [ApplicationCommandMessageClass:56  ]- NODE 2: Incoming command class SWITCH_MULTILEVEL
2015-09-22 21:11:18.347 [DEBUG] [veMultiLevelSwitchCommandClass:94  ]- NODE 2: Received Switch Multi Level Request
2015-09-22 21:11:18.348 [DEBUG] [veMultiLevelSwitchCommandClass:114 ]- NODE 2: Switch Multi Level report, value = 0
2015-09-22 21:11:18.350 [DEBUG] [b.z.i.protocol.ZWaveController:682 ]- Notifying event listeners: ZWaveCommandClassValueEvent
2015-09-22 21:11:18.351 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2015-09-22 21:11:18.352 [DEBUG] [.z.internal.ZWaveActiveBinding:450 ]- NODE 2: Got a value event from Z-Wave network, endpoint = 0, command class = SWITCH_MULTILEVEL, value = 0
2015-09-22 21:11:18.354 [WARN ] [.z.internal.ZWaveActiveBinding:467 ]- NODE 2: No item bound for event, endpoint = 0, command class = SWITCH_MULTILEVEL, value = 0, ignoring.
2015-09-22 21:11:18.356 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 02 02 26 02 
2015-09-22 21:11:18.358 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 00 02 03 26 03 00 
2015-09-22 21:11:18.359 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=ApplicationCommandHandler, expected=ApplicationCommandHandler, cancelled=false
2015-09-22 21:11:18.360 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2015-09-22 21:11:18.361 [DEBUG] [b.z.i.protocol.ZWaveController:682 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2015-09-22 21:11:18.362 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2015-09-22 21:11:18.363 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1005]- NODE 2: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true)
2015-09-22 21:11:18.364 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:201 ]- NODE 2: Node advancer - checking initialisation queue. Queue size 1.
2015-09-22 21:11:18.366 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:207 ]- NODE 2: Node advancer - message removed from queue. Queue size 0.
2015-09-22 21:11:18.367 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:267 ]- NODE 2: Node advancer - DYNAMIC_VALUES: queue length(0), free to send(true)
2015-09-22 21:11:18.368 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1098]- NODE 2: Initialisation retry timer started 5000
2015-09-22 21:11:18.369 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 2: Node advancer: loop - DYNAMIC_VALUES try 1: stageAdvanced(false)
2015-09-22 21:11:18.370 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:773 ]- NODE 2: Node advancer: DYNAMIC_VALUES - checking MANUFACTURER_SPECIFIC
2015-09-22 21:11:18.372 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:773 ]- NODE 2: Node advancer: DYNAMIC_VALUES - checking BASIC
2015-09-22 21:11:18.373 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:773 ]- NODE 2: Node advancer: DYNAMIC_VALUES - checking SWITCH_MULTILEVEL
2015-09-22 21:11:18.374 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:776 ]- NODE 2: Node advancer: DYNAMIC_VALUES - found    SWITCH_MULTILEVEL
2015-09-22 21:11:18.375 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:780 ]- NODE 2: Found 1 instances of SWITCH_MULTILEVEL
2015-09-22 21:11:18.376 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:773 ]- NODE 2: Node advancer: DYNAMIC_VALUES - checking SCENE_ACTIVATION
2015-09-22 21:11:18.377 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:773 ]- NODE 2: Node advancer: DYNAMIC_VALUES - checking VERSION
2015-09-22 21:11:18.379 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:773 ]- NODE 2: Node advancer: DYNAMIC_VALUES - checking APPLICATION_STATUS
2015-09-22 21:11:18.380 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:773 ]- NODE 2: Node advancer: DYNAMIC_VALUES - checking NO_OPERATION
2015-09-22 21:11:18.381 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:808 ]- NODE 2: Node advancer: DYNAMIC_VALUES - queued 0 frames
2015-09-22 21:11:18.382 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:860 ]- NODE 2: Node advancer - advancing to DONE
2015-09-22 21:11:18.383 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:333 ]- NODE 2: Node advancer: loop - DONE try 0: stageAdvanced(true)
2015-09-22 21:11:18.385 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:107 ]- NODE 2: Serializing to file etc/zwave/node2.xml
2015-09-22 21:11:18.413 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:819 ]- NODE 2: Node advancer: Initialisation complete!
2015-09-22 21:11:18.414 [DEBUG] [b.z.i.protocol.ZWaveController:682 ]- Notifying event listeners: ZWaveInitializationCompletedEvent
2015-09-22 21:11:18.415 [DEBUG] [.z.internal.ZWaveActiveBinding:425 ]- NODE 2: ZWaveIncomingEvent Called, Network Event, Init Done. Setting device ready.
2015-09-22 21:11:18.416 [DEBUG] [z.internal.ZWaveNetworkMonitor:730 ]- Network initialised - starting network monitor.
2015-09-22 21:11:18.418 [DEBUG] [WaveController$ZWaveSendThread:1374]- NODE 2: Response processed after 132ms/233ms.
2015-09-22 21:12:51.651 [DEBUG] [z.internal.ZWaveNetworkMonitor:341 ]- NODE 2: Sending periodic PING.
2015-09-22 21:12:51.653 [DEBUG] [c.ZWaveNoOperationCommandClass:72  ]- NODE 2: Creating new message for command No Operation
2015-09-22 21:12:51.655 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 2: Creating empty message of class = SendData (0x13), type = Request (0x00)
2015-09-22 21:12:51.656 [DEBUG] [b.z.i.protocol.ZWaveController:985 ]- Callback ID = 4
2015-09-22 21:12:51.657 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-09-22 21:12:51.659 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 08 00 13 02 01 00 25 04 C6 
2015-09-22 21:12:51.661 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 2: Sending REQUEST Message = 01 08 00 13 02 01 00 25 04 C6 
2015-09-22 21:12:51.662 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 0
2015-09-22 21:12:51.670 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 04 01 13 01 E8 
2015-09-22 21:12:51.672 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=1
2015-09-22 21:12:51.674 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:12:51.675 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 13 01 E8 
2015-09-22 21:12:51.676 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 04 01 13 01 E8 
2015-09-22 21:12:51.677 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
2015-09-22 21:12:51.678 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 2: Sent Data successfully placed on stack.
2015-09-22 21:12:51.687 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 07 00 13 04 00 00 02 ED 
2015-09-22 21:12:51.690 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=1
2015-09-22 21:12:51.692 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:12:51.694 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 09 00 13 04 00 00 02 00 00 E3 
2015-09-22 21:12:51.695 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 09 00 13 04 00 00 02 00 00 E3 
2015-09-22 21:12:51.697 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = SendData (0x13), type = Request (0x00), payload = 04 00 00 02 
2015-09-22 21:12:51.699 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 2: SendData Request. CallBack ID = 4, Status = Transmission complete and ACK received(0)
2015-09-22 21:12:51.701 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 02 01 00 
2015-09-22 21:12:51.703 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 04 00 00 02 
2015-09-22 21:12:51.704 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=SendData, expected=SendData, cancelled=false
2015-09-22 21:12:51.705 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2015-09-22 21:12:51.706 [DEBUG] [b.z.i.protocol.ZWaveController:682 ]- Notifying event listeners: ZWaveTransactionCompletedEvent
2015-09-22 21:12:51.707 [DEBUG] [.z.internal.ZWaveActiveBinding:433 ]- ZwaveIncomingEvent
2015-09-22 21:12:51.709 [DEBUG] [WaveController$ZWaveSendThread:1374]- NODE 2: Response processed after 47ms/233ms.
2015-09-22 21:14:21.667 [DEBUG] [z.internal.ZWaveNetworkMonitor:341 ]- NODE 2: Sending periodic PING.
2015-09-22 21:14:21.669 [DEBUG] [c.ZWaveNoOperationCommandClass:72  ]- NODE 2: Creating new message for command No Operation
2015-09-22 21:14:21.671 [DEBUG] [o.b.z.i.protocol.SerialMessage:109 ]- NODE 2: Creating empty message of class = SendData (0x13), type = Request (0x00)
2015-09-22 21:14:21.672 [DEBUG] [b.z.i.protocol.ZWaveController:985 ]- Callback ID = 5
2015-09-22 21:14:21.674 [DEBUG] [WaveController$ZWaveSendThread:1258]- Took message from queue for sending. Queue length = 0
2015-09-22 21:14:21.675 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 08 00 13 02 01 00 25 05 C7 
2015-09-22 21:14:21.677 [DEBUG] [WaveController$ZWaveSendThread:1315]- NODE 2: Sending REQUEST Message = 01 08 00 13 02 01 00 25 05 C7 
2015-09-22 21:14:21.681 [DEBUG] [b.z.i.protocol.ZWaveController:667 ]- Enqueueing message. Queue length = 0
2015-09-22 21:14:21.687 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 04 01 13 01 E8 
2015-09-22 21:14:21.690 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:14:21.692 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 04 01 13 01 E8 
2015-09-22 21:14:21.693 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 04 01 13 01 E8 
2015-09-22 21:14:21.695 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
2015-09-22 21:14:21.695 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=0
2015-09-22 21:14:21.696 [DEBUG] [b.z.i.p.s.SendDataMessageClass:38  ]- NODE 2: Sent Data successfully placed on stack.
2015-09-22 21:14:21.704 [DEBUG] [eController$ZWaveReceiveThread:1528]- Receive Message = 01 07 00 13 05 00 00 02 EC 
2015-09-22 21:14:21.707 [DEBUG] [eController$ZWaveReceiveThread:1452]- Receive queue ADD: Length=1
2015-09-22 21:14:21.707 [DEBUG] [b.z.i.protocol.ZWaveController:1210]- Receive queue TAKE: Length=0
2015-09-22 21:14:21.710 [DEBUG] [o.b.z.i.protocol.SerialMessage:233 ]- Assembled message buffer = 01 09 00 13 05 00 00 02 00 00 E2 
2015-09-22 21:14:21.712 [DEBUG] [b.z.i.protocol.ZWaveController:1211]- Process Message = 01 09 00 13 05 00 00 02 00 00 E2 
2015-09-22 21:14:21.713 [DEBUG] [b.z.i.protocol.ZWaveController:190 ]- Message: class = SendData (0x13), type = Request (0x00), payload = 05 00 00 02 
2015-09-22 21:14:21.714 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 2: SendData Request. CallBack ID = 5, Status = Transmission complete and ACK received(0)
2015-09-22 21:14:21.716 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:63  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 02 01 00 
2015-09-22 21:14:21.717 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:64  ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 05 00 00 02 
2015-09-22 21:14:21.718 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:65  ]- Checking transaction complete: class=SendData, expected=SendData, cancelled=false
2015-09-22 21:14:21.719 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:68  ]-          transaction complete!
2015-09-22 21:14:21.720 [DEBUG] [b.z.i.protocol.ZWaveController:682 ]- Notifying event listeners: ZWaveTransactionCompletedEvent

Branden_Smale · September 23, 2015, 11:53am

node 2 is a plugin lamp dimmer by leviton. i have not defined it yet as an item, been trying to get habmin up to do it there. node 1 is the zstick. those are the only nodes at this time, i have more, just want to keep it simple, yet its still been so hard.

Branden_Smale · September 23, 2015, 12:33pm

I may have found my issue.
https://groups.google.com/forum/m/#!topic/openhab2/AeK6YYkZO5g

Last post. Thought I did this, but not 100% sure anymore, so much has been done. I’ll try it this afternoon.

bob_dickenson · September 23, 2015, 5:35pm

in Habmin1 the port spec is in /configurations/openhab.cfg Search for z-wave.

chris · September 23, 2015, 6:32pm

@Branden_Smale when posting logs, please format appropriately by selecting the code, and then clicking the </> button. Otherwise the posts become difficult to read…

I’ll update your posts…

Chris

Branden_Smale · September 23, 2015, 6:40pm

so, i did specify the port in openhab.cfg. Why are my nodes not showing up in habmin? are the logs ok? i get “Network error loading zwave device list”

Branden_Smale · September 23, 2015, 7:43pm

I have figured out the problem, but dont know how to fix it.

Start the pi, autostart of openhab daemon starts.
Login
Startx
open terminal and sudo service openhab stop
sudo /opt/openhab/start.sh

nodes show up in the zwave list in habmin.

Apparently is a problem with the openhab daemon. How do I fix this?

Branden_Smale · September 23, 2015, 8:49pm

next is:

Have my switch in sitemap but when I do it I get this in the log.

2015-09-23 16:46:38.213 [INFO ] [runtime.busevents             ] - Lamp received command OFF
2015-09-23 16:46:38.259 [WARN ] [t.i.s.MapTransformationService] - Could not find a mapping for '-' in the file 'en.map'.

indent preformatted text by 4 spaces

Branden_Smale · September 23, 2015, 9:09pm

Nevermind, that was my bad in how I set up the item. But now the dimmer just doesn’t turn on or off, even though I get no warnings in the log. The log looks good, but lamp don’t turn on or off.

bob_dickenson · September 23, 2015, 11:52pm

for a dimmer you need to sendCommand(devicename, number-between-zero-and-one-hundred representing the percentage of ON-ness)

Branden_Smale · September 24, 2015, 1:07am

So I can’t set it as a switch_binary?

And what do I do about the autostart daemon?

bob_dickenson · September 24, 2015, 11:03am

I don’t use the autostart daemon myself, so can’t help you on that.

Looking at your earlier log, I do not see that Node 2 has responded with SWITCH_BINARY as a valid command class, only SWITCH_MULTILEVEL.

Branden_Smale · September 24, 2015, 11:36am

Yeah, I appreciate it, got it working
Just need to fix the daemon.

bob_dickenson · September 24, 2015, 11:56am

Good. You might want to disable the daemon for a while as you tinker with things.

Guessing maybe the daemon starting up too quickly before the /dev/ttyXX where your stick is…but just a guess.

Those zwave logs will be a great help to you as you add more devices…when I add something new, usually have a separate windows just tailing the zwave log. (I have maybe 10 different loggers for different rooms/areas of the house and/or subsystems. Really helpful in sorting out the various message streams when you are fiddling with a production system.)

Good luck !

Branden_Smale · September 25, 2015, 10:39am

Thanks for all your help

bob_dickenson · September 26, 2015, 12:19am

No problem. You are welcome.