just a guess, but the stale lock file which cannot be removed may be left over from an earlier attempt running as a different user and the current user does not have permissions to clean it up.
I’d sudo rm the lock file and try again
Should I also chown that directory to the user openhab?
Also, what are all the directories that user openhab need access too? Should I chown all these directories?
I would sudo rm the stale lock file. sudo chown the openhab subtree only. Run as the openhab user.
Then the new lock file will be created by that user and subsequent attempts to delete (ie at OH startup) should succeed since the openhab user is the creator/owner of the (now-stale) lock file.
Make sense ?
Ok, I will try it.
ok, i did that, and the nodes load up in the log again, but still arent visible in habmin. at this point, i just want to start over with a clean install. are you willing to walk me through exactly what you have done, maybe then i will be on the same page as you and if im still having issues, then maybe it could be hardware issue. it would be really great if you could walk me through.
Before you toast everything, let’s do a little “horsy-doggy-ducky”.
So (being overly explicit)…when you say the “nodes load up in the log again” , do you mean they show in the zwave log ? (configured in logback.xml)…you should have this set to a DEBUG level until this gets straightened out.
Again being overly explicit, in my own logback.xml (or logback_debug.xml ), (hit by ./start.sh and ./start_debug.sh, respectively) I have the following entries:
logs/zwave.log
logs/zwave-%d{yyyy-ww}.log.zip
30
%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level %logger{30}[:%line]- %msg%n%ex{5}
and
IF the nodes show in the zwave log, you’ll see the nodes getting acquired by the controller and (pretty voluminous) chatter along the network. At the near beginning of the log you’ll find a listing of the node numbers that are known to the controller (this is before all the “is it dead/alive/Schodinger’s node” chatter.
If you do not see the nodes listed at the near-beginning of the zwave log, then you should look at your node inclusion/exclusion discipline. (Been bit by this myself). Are the nodes included in your controller ? I don’t mean included by habmin, I mean have you walked around to your devices, z-stick in hand, put your z-stick into inclusion mode and seen the lights flashing with the “I’ve got you” signalling. (word of advice, given the number of times your been round the barn here, you’ll like be tempted to try an re-include your devices. I would recommend that for each device, you first do an “exclude” cycle before any “include”.)
If you do see the nodes at the beginning of the zwave log, then you have to look at the detailed messages in the DEBUG log to see what might be going on here. I’ll (of course) defer to @chris on the details, but deep in the log weeds you can find useful info sometimes.
When I go to a terminal and type /opt/openhab/start.sh. the pi starts up which is what I refer to as log. I get open port, port inialized, node 1 found, node 2 found, etc
I added per zwave binding page at github in logback.xml. now, how do I view it?
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 = falseThe 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” .
There is also node 2. I could only post 32000 chatacters. Yes, it is included, and it is communicating according to the log
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)
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: ZWaveTransactionCompletedEventnode 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.
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.
in Habmin1 the port spec is in /configurations/openhab.cfg Search for z-wave.
@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
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”
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?
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