Z-Wave problem with new modules

smillier · January 16, 2018, 10:10am

I was able to enable trace logs and see below the traces. Node 34 is one of my FGR222 in an unknown state:
pi@OpenHab:/var/log/openhab2 $ cat openhab.log | grep 'NODE 34’
2018-01-16 09:57:56.794 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Stage INIT_NEIGHBORS. Initialisation retry timer triggered. Increased to 10000
2018-01-16 09:58:04.300 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - INIT_NEIGHBORS: queue length(0), free to send(false)
2018-01-16 09:58:04.316 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Initialisation retry timer started 10000
2018-01-16 09:58:04.349 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - INIT_NEIGHBORS try 1: stageAdvanced(false)
2018-01-16 09:58:04.358 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: INIT_NEIGHBORS - send RoutingInfo
2018-01-16 09:58:04.371 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 34: Request routing info
2018-01-16 09:58:04.382 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - queued packet. Queue length is 1
2018-01-16 09:58:06.606 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: ProtocolInfo
2018-01-16 09:58:06.606 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Listening = true
2018-01-16 09:58:06.607 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Routing = true
2018-01-16 09:58:06.607 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Beaming = true
2018-01-16 09:58:06.608 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Version = 4
2018-01-16 09:58:06.608 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: FLIRS = false
2018-01-16 09:58:06.609 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Security = false
2018-01-16 09:58:06.609 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Max Baud = 40000
2018-01-16 09:58:06.609 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Basic = Routing Slave
2018-01-16 09:58:06.610 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Generic = Multi-Level Switch
2018-01-16 09:58:06.610 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Specific = Motor Control Class B
2018-01-16 09:58:06.611 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Creating new instance of command class NO_OPERATION
2018-01-16 09:58:06.621 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Command class NO_OPERATION, endpoint null created
2018-01-16 09:58:06.622 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Version = 1, version set. Enabling extra functionality.
2018-01-16 09:58:06.623 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Creating new instance of command class BASIC
2018-01-16 09:58:06.625 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Command class BASIC, endpoint null created
2018-01-16 09:58:06.634 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Creating new instance of command class SWITCH_MULTILEVEL
2018-01-16 09:58:06.636 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Command class SWITCH_MULTILEVEL, endpoint null created
2018-01-16 09:58:06.637 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Creating new instance of command class SWITCH_BINARY
2018-01-16 09:58:06.638 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Command class SWITCH_BINARY, endpoint null created
2018-01-16 09:58:06.638 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Creating new instance of command class VERSION
2018-01-16 09:58:06.638 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Command class VERSION, endpoint null created
2018-01-16 09:58:06.642 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Creating new instance of command class MANUFACTURER_SPECIFIC
2018-01-16 09:58:06.644 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Command class MANUFACTURER_SPECIFIC, endpoint null created
2018-01-16 09:58:06.648 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - INIT_NEIGHBORS: Transaction complete (IdentifyNode:Request) success(true)
2018-01-16 09:58:06.649 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - checking initialisation queue. Queue size 1.
2018-01-16 09:58:06.681 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: ProtocolInfo
2018-01-16 09:58:06.681 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Listening = true
2018-01-16 09:58:06.682 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Routing = true
2018-01-16 09:58:06.682 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Beaming = true
2018-01-16 09:58:06.683 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Version = 4
2018-01-16 09:58:06.683 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: FLIRS = false
2018-01-16 09:58:06.684 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Security = false
2018-01-16 09:58:06.684 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Max Baud = 40000
2018-01-16 09:58:06.685 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Basic = Routing Slave
2018-01-16 09:58:06.686 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Generic = Multi-Level Switch
2018-01-16 09:58:06.686 [DEBUG] [rialmessage.IdentifyNodeMessageClass] - NODE 34: Specific = Motor Control Class B
2018-01-16 09:58:06.687 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Creating new instance of command class NO_OPERATION
2018-01-16 09:58:06.688 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Command class NO_OPERATION, endpoint null created
2018-01-16 09:58:06.688 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Version = 1, version set. Enabling extra functionality.
2018-01-16 09:58:06.689 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Creating new instance of command class BASIC
2018-01-16 09:58:06.689 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Command class BASIC, endpoint null created
2018-01-16 09:58:06.690 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Creating new instance of command class SWITCH_MULTILEVEL
2018-01-16 09:58:06.691 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Command class SWITCH_MULTILEVEL, endpoint null created
2018-01-16 09:58:06.691 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Creating new instance of command class SWITCH_BINARY
2018-01-16 09:58:06.692 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Command class SWITCH_BINARY, endpoint null created
2018-01-16 09:58:06.694 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Creating new instance of command class VERSION
2018-01-16 09:58:06.695 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Command class VERSION, endpoint null created
2018-01-16 09:58:06.697 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Creating new instance of command class MANUFACTURER_SPECIFIC
2018-01-16 09:58:06.697 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 34: Command class MANUFACTURER_SPECIFIC, endpoint null created
2018-01-16 09:58:06.702 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - INIT_NEIGHBORS: Transaction complete (IdentifyNode:Request) success(true)
2018-01-16 09:58:06.703 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - checking initialisation queue. Queue size 1.
2018-01-16 09:58:09.359 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 34: Got NodeRoutingInfo request.
2018-01-16 09:58:09.359 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 34: Neighbor nodes: 1 8 9 12 14 21 23 33 35
2018-01-16 09:58:09.364 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - INIT_NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true)
2018-01-16 09:58:09.364 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - checking initialisation queue. Queue size 1.
2018-01-16 09:58:09.365 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - message removed from queue. Queue size 0.
2018-01-16 09:58:09.366 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - INIT_NEIGHBORS: queue length(0), free to send(true)
2018-01-16 09:58:09.367 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Initialisation retry timer started 10000
2018-01-16 09:58:09.367 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - INIT_NEIGHBORS try 2: stageAdvanced(false)
2018-01-16 09:58:09.368 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - advancing to FAILED_CHECK
2018-01-16 09:58:09.369 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true)
2018-01-16 09:58:09.370 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 34: Requesting IsFailedNode status from controller.
2018-01-16 09:58:09.383 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - queued packet. Queue length is 1
2018-01-16 09:58:11.933 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 34: Got NodeRoutingInfo request.
2018-01-16 09:58:11.933 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 34: Neighbor nodes: 1 8 9 12 14 21 23 33 35
2018-01-16 09:58:11.938 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - FAILED_CHECK: Transaction complete (GetRoutingInfo:Request) success(true)
2018-01-16 09:58:11.939 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - checking initialisation queue. Queue size 1.
2018-01-16 09:58:14.336 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 34: Is currently marked as healthy by the controller
2018-01-16 09:58:14.340 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true)
2018-01-16 09:58:14.341 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - checking initialisation queue. Queue size 1.
2018-01-16 09:58:14.342 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - message removed from queue. Queue size 0.
2018-01-16 09:58:14.342 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - FAILED_CHECK: queue length(0), free to send(true)
2018-01-16 09:58:14.343 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Initialisation retry timer started 5000
2018-01-16 09:58:14.348 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false)
2018-01-16 09:58:14.350 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - advancing to WAIT
2018-01-16 09:58:14.352 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - WAIT try 0: stageAdvanced(true)
2018-01-16 09:58:14.353 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: WAIT - Listening=true, FrequentlyListening=false
2018-01-16 09:58:14.353 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: WAIT - Advancing
2018-01-16 09:58:14.354 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - advancing to PING
2018-01-16 09:58:14.355 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - PING try 0: stageAdvanced(true)
2018-01-16 09:58:14.356 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: PING - send NoOperation
2018-01-16 09:58:14.356 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 34: Creating new message for command No Operation
2018-01-16 09:58:14.357 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 34: Creating empty message of class = SendData (0x13), type = Request (0x00)
2018-01-16 09:58:14.357 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - queued packet. Queue length is 1
2018-01-16 09:58:19.343 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Stage PING. Initialisation retry timer triggered. Increased to 10000
2018-01-16 09:58:19.344 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - PING: queue length(0), free to send(false)
2018-01-16 09:58:19.345 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Initialisation retry timer started 10000
2018-01-16 09:58:19.345 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - PING try 1: stageAdvanced(false)
2018-01-16 09:58:19.346 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: PING - send NoOperation
2018-01-16 09:58:19.347 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 34: Creating new message for command No Operation
2018-01-16 09:58:19.347 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 34: Creating empty message of class = SendData (0x13), type = Request (0x00)
2018-01-16 09:58:19.348 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - queued packet. Queue length is 1
2018-01-16 09:58:29.346 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Stage PING. Initialisation retry timer triggered. Increased to 20000
2018-01-16 09:58:29.690 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - PING: queue length(0), free to send(false)
2018-01-16 09:58:29.703 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Initialisation retry timer started 20000
2018-01-16 09:58:29.704 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - PING try 2: stageAdvanced(false)
2018-01-16 09:58:29.704 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: PING - send NoOperation
2018-01-16 09:58:29.705 [DEBUG] [ndclass.ZWaveNoOperationCommandClass] - NODE 34: Creating new message for command No Operation
2018-01-16 09:58:29.706 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 34: Creating empty message of class = SendData (0x13), type = Request (0x00)
2018-01-16 09:58:29.708 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - queued packet. Queue length is 1
2018-01-16 09:58:47.202 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 34: Sending REQUEST Message = 01 08 00 13 22 01 00 25 04 E6
2018-01-16 09:58:47.221 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: Sent Data successfully placed on stack.
2018-01-16 09:58:47.279 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: SendData Request. CallBack ID = 4, Status = Transmission complete and ACK received(0)
2018-01-16 09:58:47.280 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 34: Node is ALIVE. Init stage is PING.
2018-01-16 09:58:47.281 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node Status event during initialisation - Node is ALIVE
2018-01-16 09:58:47.281 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - PING: queue length(1), free to send(false)
2018-01-16 09:58:47.282 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Initialisation retry timer started 20000
2018-01-16 09:58:47.283 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - queued packet. Queue length is 1
2018-01-16 09:58:47.286 [TRACE] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node Status event during initialisation processed
2018-01-16 09:58:47.286 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 34: Node Status event - Node is ALIVE
2018-01-16 09:58:47.291 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - PING: Transaction complete (SendData:Request) success(true)
2018-01-16 09:58:47.292 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - checking initialisation queue. Queue size 1.
2018-01-16 09:58:47.293 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - message removed from queue. Queue size 0.
2018-01-16 09:58:47.293 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - PING: queue length(0), free to send(true)
2018-01-16 09:58:47.294 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Initialisation retry timer started 20000
2018-01-16 09:58:47.295 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - PING try 3: stageAdvanced(false)
2018-01-16 09:58:47.296 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - advancing to DETAILS
2018-01-16 09:58:47.298 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - DETAILS try 0: stageAdvanced(true)
2018-01-16 09:58:47.298 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: Restored from file - skipping static initialisation
2018-01-16 09:58:47.299 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - advancing to GET_CONFIGURATION
2018-01-16 09:58:47.301 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - GET_CONFIGURATION try 0: stageAdvanced(true)
2018-01-16 09:58:47.309 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: GET_CONFIGURATION - thing is null!
2018-01-16 09:58:47.310 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - advancing to DYNAMIC_VALUES
2018-01-16 09:58:47.312 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - DYNAMIC_VALUES try 0: stageAdvanced(true)
2018-01-16 09:58:47.312 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking METER
2018-01-16 09:58:47.313 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - found METER
2018-01-16 09:58:47.314 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Found 1 instances of METER
2018-01-16 09:58:47.315 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 34: Creating new message for application command METER_GET
2018-01-16 09:58:47.316 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 34: Creating empty message of class = SendData (0x13), type = Request (0x00)
2018-01-16 09:58:47.317 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 34: Creating new message for application command METER_GET
2018-01-16 09:58:47.318 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 34: Creating empty message of class = SendData (0x13), type = Request (0x00)
2018-01-16 09:58:47.319 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - queued packet. Queue length is 1
2018-01-16 09:58:47.322 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking MANUFACTURER_SPECIFIC
2018-01-16 09:58:47.323 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking BASIC
2018-01-16 09:58:47.324 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking SWITCH_MULTILEVEL
2018-01-16 09:58:47.324 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - found SWITCH_MULTILEVEL
2018-01-16 09:58:47.325 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Found 1 instances of SWITCH_MULTILEVEL
2018-01-16 09:58:47.326 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 34: Creating new message for command SWITCH_MULTILEVEL_GET
2018-01-16 09:58:47.327 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 34: Creating empty message of class = SendData (0x13), type = Request (0x00)
2018-01-16 09:58:47.328 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking VERSION
2018-01-16 09:58:47.329 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking SENSOR_MULTILEVEL
2018-01-16 09:58:47.330 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - found SENSOR_MULTILEVEL
2018-01-16 09:58:47.330 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Found 1 instances of SENSOR_MULTILEVEL
2018-01-16 09:58:47.331 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 34: Creating new message for command SENSOR_MULTI_LEVEL_GET
2018-01-16 09:58:47.332 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 34: Creating empty message of class = SendData (0x13), type = Request (0x00)
2018-01-16 09:58:47.333 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking MULTI_INSTANCE_ASSOCIATION
2018-01-16 09:58:47.334 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking PROTECTION
2018-01-16 09:58:47.335 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - found PROTECTION
2018-01-16 09:58:47.335 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Found 1 instances of PROTECTION
2018-01-16 09:58:47.336 [DEBUG] [andclass.ZWaveProtectionCommandClass] - NODE 34: Creating new message for command PROTECTION_GET
2018-01-16 09:58:47.337 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 34: Creating empty message of class = SendData (0x13), type = Request (0x00)
2018-01-16 09:58:47.338 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking NO_OPERATION
2018-01-16 09:58:47.339 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking POWERLEVEL
2018-01-16 09:58:47.339 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - found POWERLEVEL
2018-01-16 09:58:47.340 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Found 1 instances of POWERLEVEL
2018-01-16 09:58:47.341 [DEBUG] [andclass.ZWavePowerLevelCommandClass] - NODE 34: Creating new message for application command POWERLEVEL_GET
2018-01-16 09:58:47.342 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 34: Creating empty message of class = SendData (0x13), type = Request (0x00)
2018-01-16 09:58:47.343 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking ASSOCIATION
2018-01-16 09:58:47.344 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking SWITCH_BINARY
2018-01-16 09:58:47.345 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer:

smillier · January 16, 2018, 10:11am

DYNAMIC_VALUES - found SWITCH_BINARY
2018-01-16 09:58:47.345 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Found 1 instances of SWITCH_BINARY
2018-01-16 09:58:47.346 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 34: Creating new message for application command SWITCH_BINARY_GET
2018-01-16 09:58:47.347 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 34: Creating empty message of class = SendData (0x13), type = Request (0x00)
2018-01-16 09:58:47.348 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking CONFIGURATION
2018-01-16 09:58:47.349 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - queued 7 frames
2018-01-16 09:58:47.350 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 34: Response processed after 147ms/4245ms.
2018-01-16 09:58:47.354 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 34: Sending REQUEST Message = 01 0A 00 13 22 03 32 01 10 25 2C ED
2018-01-16 09:58:47.372 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: Sent Data successfully placed on stack.
2018-01-16 09:58:47.428 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: SendData Request. CallBack ID = 44, Status = Transmission complete and ACK received(0)
2018-01-16 09:58:47.478 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 34: Application Command Request (ALIVE:DYNAMIC_VALUES)
2018-01-16 09:58:47.478 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 34: Incoming command class METER
2018-01-16 09:58:47.479 [TRACE] [ssage.ApplicationCommandMessageClass] - NODE 34: Found Command Class METER, passing to handleApplicationCommandRequest
2018-01-16 09:58:47.479 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 34: Received METER command V2
2018-01-16 09:58:47.480 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 34: Meter: Type=Electric(1), Scale=W(2), Value=0E+1
2018-01-16 09:58:47.484 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true)
2018-01-16 09:58:47.484 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - checking initialisation queue. Queue size 7.
2018-01-16 09:58:47.485 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - message removed from queue. Queue size 6.
2018-01-16 09:58:47.485 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - DYNAMIC_VALUES: queue length(6), free to send(true)
2018-01-16 09:58:47.486 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Initialisation retry timer started 5000
2018-01-16 09:58:47.486 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - queued packet. Queue length is 6
2018-01-16 09:58:47.488 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 34: Response processed after 133ms/4245ms.
2018-01-16 09:58:47.491 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 34: Sending REQUEST Message = 01 0A 00 13 22 03 32 01 00 25 2D FC
2018-01-16 09:58:47.509 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: Sent Data successfully placed on stack.
2018-01-16 09:58:47.604 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: SendData Request. CallBack ID = 45, Status = Transmission complete and ACK received(0)
2018-01-16 09:58:47.655 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 34: Application Command Request (ALIVE:DYNAMIC_VALUES)
2018-01-16 09:58:47.655 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 34: Incoming command class METER
2018-01-16 09:58:47.656 [TRACE] [ssage.ApplicationCommandMessageClass] - NODE 34: Found Command Class METER, passing to handleApplicationCommandRequest
2018-01-16 09:58:47.656 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 34: Received METER command V2
2018-01-16 09:58:47.657 [DEBUG] [.commandclass.ZWaveMeterCommandClass] - NODE 34: Meter: Type=Electric(1), Scale=kWh(0), Value=0E+1
2018-01-16 09:58:47.661 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true)
2018-01-16 09:58:47.661 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - checking initialisation queue. Queue size 6.
2018-01-16 09:58:47.662 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - message removed from queue. Queue size 5.
2018-01-16 09:58:47.662 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - DYNAMIC_VALUES: queue length(5), free to send(true)
2018-01-16 09:58:47.663 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Initialisation retry timer started 5000
2018-01-16 09:58:47.663 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - queued packet. Queue length is 5
2018-01-16 09:58:47.665 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 34: Response processed after 173ms/4245ms.
2018-01-16 09:58:47.668 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 34: Sending REQUEST Message = 01 09 00 13 22 02 26 02 25 2E EA
2018-01-16 09:58:47.686 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: Sent Data successfully placed on stack.
2018-01-16 09:58:47.783 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: SendData Request. CallBack ID = 46, Status = Transmission complete and ACK received(0)
2018-01-16 09:58:47.830 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 34: Application Command Request (ALIVE:DYNAMIC_VALUES)
2018-01-16 09:58:47.831 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 34: Incoming command class SWITCH_MULTILEVEL
2018-01-16 09:58:47.831 [TRACE] [ssage.ApplicationCommandMessageClass] - NODE 34: Found Command Class SWITCH_MULTILEVEL, passing to handleApplicationCommandRequest
2018-01-16 09:58:47.832 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 34: Received SWITCH_MULTILEVEL command V3
2018-01-16 09:58:47.832 [DEBUG] [ss.ZWaveMultiLevelSwitchCommandClass] - NODE 34: Switch Multi Level report, value = 99
2018-01-16 09:58:47.836 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true)
2018-01-16 09:58:47.836 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - checking initialisation queue. Queue size 5.
2018-01-16 09:58:47.837 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - message removed from queue. Queue size 4.
2018-01-16 09:58:47.837 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - DYNAMIC_VALUES: queue length(4), free to send(true)
2018-01-16 09:58:47.838 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Initialisation retry timer started 5000
2018-01-16 09:58:47.838 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - queued packet. Queue length is 4
2018-01-16 09:58:47.840 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 34: Response processed after 171ms/4245ms.
2018-01-16 09:58:47.843 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 34: Sending REQUEST Message = 01 09 00 13 22 02 31 04 25 2F FA
2018-01-16 09:58:47.860 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: Sent Data successfully placed on stack.
2018-01-16 09:58:47.917 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: SendData Request. CallBack ID = 47, Status = Transmission complete and ACK received(0)
2018-01-16 09:58:47.974 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 34: Application Command Request (ALIVE:DYNAMIC_VALUES)
2018-01-16 09:58:47.975 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 34: Incoming command class SENSOR_MULTILEVEL
2018-01-16 09:58:47.976 [TRACE] [ssage.ApplicationCommandMessageClass] - NODE 34: Found Command Class SENSOR_MULTILEVEL, passing to handleApplicationCommandRequest
2018-01-16 09:58:47.976 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 34: Received COMMAND_CLASS_SENSOR_MULTILEVEL command V2
2018-01-16 09:58:47.977 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 34: Sensor Multi Level REPORT received
2018-01-16 09:58:47.978 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 34: Sensor Type = Power(4), Scale = 0
2018-01-16 09:58:47.979 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 34: Sensor Value = 0E+1
2018-01-16 09:58:47.988 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true)
2018-01-16 09:58:47.989 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - checking initialisation queue. Queue size 4.
2018-01-16 09:58:47.990 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - message removed from queue. Queue size 3.
2018-01-16 09:58:47.990 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - DYNAMIC_VALUES: queue length(3), free to send(true)
2018-01-16 09:58:47.991 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Initialisation retry timer started 5000
2018-01-16 09:58:47.992 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - queued packet. Queue length is 3
2018-01-16 09:58:47.996 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 34: Response processed after 152ms/4245ms.
2018-01-16 09:58:48.001 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 34: Sending REQUEST Message = 01 09 00 13 22 02 75 02 25 30 A7
2018-01-16 09:58:48.027 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: Sent Data successfully placed on stack.
2018-01-16 09:58:48.126 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: SendData Request. CallBack ID = 48, Status = Transmission complete and ACK received(0)
2018-01-16 09:58:48.160 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 34: Application Command Request (ALIVE:DYNAMIC_VALUES)
2018-01-16 09:58:48.161 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 34: Incoming command class PROTECTION
2018-01-16 09:58:48.162 [TRACE] [ssage.ApplicationCommandMessageClass] - NODE 34: Found Command Class PROTECTION, passing to handleApplicationCommandRequest
2018-01-16 09:58:48.163 [DEBUG] [andclass.ZWaveProtectionCommandClass] - NODE 34: Received PROTECTION command V2
2018-01-16 09:58:48.165 [DEBUG] [andclass.ZWaveProtectionCommandClass] - NODE 34: Received protection report local:UNPROTECTED rf:UNPROTECTED
2018-01-16 09:58:48.171 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true)
2018-01-16 09:58:48.172 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - checking initialisation queue. Queue size 3.
2018-01-16 09:58:48.173 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - message removed from queue. Queue size 2.
2018-01-16 09:58:48.174 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - DYNAMIC_VALUES: queue length(2), free to send(true)
2018-01-16 09:58:48.176 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Initialisation retry timer started 5000
2018-01-16 09:58:48.177 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - queued packet. Queue length is 2
2018-01-16 09:58:48.180 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 34: Response processed after 177ms/4245ms.
2018-01-16 09:58:48.186 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 34: Sending REQUEST Message = 01 09 00 13 22 02 73 02 25 31 A0
2018-01-16 09:58:48.240 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: Sent Data successfully placed on stack.
2018-01-16 09:58:48.275 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: SendData Request. CallBack ID = 49, Status = Transmission complete and ACK received(0)
2018-01-16 09:58:48.347 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 34: Application Command Request (ALIVE:DYNAMIC_VALUES)
2018-01-16 09:58:48.348 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 34: Incoming command class POWERLEVEL
2018-01-16 09:58:48.349 [TRACE] [ssage.ApplicationCommandMessageClass] - NODE 34: Found Command Class POWERLEVEL, passing to handleApplicationCommandRequest
2018-01-16 09:58:48.352 [DEBUG] [andclass.ZWavePowerLevelCommandClass] - NODE 34: Received POWERLEVEL command V1
2018-01-16 09:58:48.353 [DEBUG] [andclass.ZWavePowerLevelCommandClass] - NODE 34: Received POWERLEVEL report -0dB with 0 second timeout
2018-01-16 09:58:48.359 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true)
2018-01-16 09:58:48.360 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - checking initialisation queue. Queue size 2.
2018-01-16 09:58:48.361 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - message removed from queue. Queue size 1.
2018-01-16 09:58:48.362 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - DYNAMIC_VALUES: queue length(1), free to send(true)
2018-01-16 09:58:48.363 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Initialisation retry timer started 5000
2018-01-16 09:58:48.364 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - queued packet. Queue length is 1
2018-01-16 09:58:48.367 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 34: Response processed after 179ms/4245ms.
2018-01-16 09:58:48.373 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 34: Sending REQUEST Message = 01 09 00 13 22 02 25 02 25 32 F5
2018-01-16 09:58:48.399 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: Sent Data successfully placed on stack.
2018-01-16 09:58:48.472 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: SendData Request. CallBack ID = 50, Status = Transmission complete and ACK received(0)
2018-01-16 09:58:48.516 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 34: Application Command Request (ALIVE:DYNAMIC_VALUES)
2018-01-16 09:58:48.517 [DEBUG] [ssage.ApplicationCommandMessageClass] - NODE 34: Incoming command class SWITCH_BINARY
2018-01-16 09:58:48.518 [TRACE] [ssage.ApplicationCommandMessageClass] - NODE 34: Found Command Class SWITCH_BINARY, passing to handleApplicationCommandRequest
2018-01-16 09:58:48.520 [DEBUG] [dclass.ZWaveBinarySwitchCommandClass] - NODE 34: Switch Binary report, value = 255
2018-01-16 09:58:48.527 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true)
2018-01-16 09:58:48.528 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - checking initialisation queue. Queue size 1.
2018-01-16 09:58:48.529 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - message removed from queue. Queue size 0.
2018-01-16 09:58:48.530 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - DYNAMIC_VALUES: queue length(0), free to send(true)
2018-01-16 09:58:48.531 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Initialisation retry timer started 5000
2018-01-16 09:58:48.532 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - DYNAMIC_VALUES try 1: stageAdvanced(false)
2018-01-16 09:58:48.533 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking METER
2018-01-16 09:58:48.534 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - found METER
2018-01-16 09:58:48.535 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Found 1 instances of METER
2018-01-16 09:58:48.535 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking MANUFACTURER_SPECIFIC
2018-01-16 09:58:48.536 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking BASIC
2018-01-16 09:58:48.537 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking SWITCH_MULTILEVEL
2018-01-16 09:58:48.538 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - found SWITCH_MULTILEVEL
2018-01-16 09:58:48.539 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Found 1 instances of SWITCH_MULTILEVEL
2018-01-16 09:58:48.540 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking VERSION
2018-01-16 09:58:48.541 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking SENSOR_MULTILEVEL
2018-01-16 09:58:48.545 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - found SENSOR_MULTILEVEL
2018-01-16 09:58:48.546 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Found 1 instances of SENSOR_MULTILEVEL
2018-01-16 09:58:48.547 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking MULTI_INSTANCE_ASSOCIATION
2018-01-16 09:58:48.548 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking PROTECTION
2018-01-16 09:58:48.549 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - found PROTECTION
2018-01-16 09:58:48.550 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Found 1 instances of PROTECTION
2018-01-16 09:58:48.550 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking NO_OPERATION
2018-01-16 09:58:48.551 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking POWERLEVEL
2018-01-16 09:58:48.552 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - found POWERLEVEL
2018-01-16 09:58:48.553 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Found 1 instances of POWERLEVEL
2018-01-16 09:58:48.554 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking ASSOCIATION
2018-01-16 09:58:48.555 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking SWITCH_BINARY
2018-01-16 09:58:48.556 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - found SWITCH_BINARY
2018-01-16 09:58:48.557 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Found 1 instances of SWITCH_BINARY
2018-01-16 09:58:48.558 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - checking CONFIGURATION
2018-01-16 09:58:48.559 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: DYNAMIC_VALUES - queued 0 frames
2018-01-16 09:58:48.560 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - advancing to DYNAMIC_END
2018-01-16 09:58:48.562 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - DYNAMIC_END try 0: stageAdvanced(true)
2018-01-16 09:58:48.563 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 34: Serializing to file /var/lib/openhab2/zwave/node34.xml
2018-01-16 09:58:48.596 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - advancing to HEAL_START
2018-01-16 09:58:48.598 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - HEAL_START try 0: stageAdvanced(true)
2018-01-16 09:58:48.599 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - advancing to DELETE_ROUTES
2018-01-16 09:58:48.602 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - DELETE_ROUTES try 0: stageAdvanced(true)
2018-01-16 09:58:48.604 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 34: Generate return routes list
2018-01-16 09:58:48.605 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 34: No return routes required.
2018-01-16 09:58:48.606 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - advancing to RETURN_ROUTES
2018-01-16 09:58:48.608 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - RETURN_ROUTES try 0: stageAdvanced(true)
2018-01-16 09:58:48.609 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 34: Generate return routes list
2018-01-16 09:58:48.610 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 34: No return routes required.
2018-01-16 09:58:48.611 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - advancing to NEIGHBORS
2018-01-16 09:58:48.613 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true)
2018-01-16 09:58:48.614 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: NEIGHBORS - get RoutingInfo
2018-01-16 09:58:48.615 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 34: Request routing info
2018-01-16 09:58:48.617 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - queued packet. Queue length is 1
2018-01-16 09:58:48.619 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 34: Response processed after 244ms/4245ms.
2018-01-16 09:58:48.640 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 34: Got NodeRoutingInfo request.
2018-01-16 09:58:48.640 [DEBUG] [almessage.GetRoutingInfoMessageClass] - NODE 34: Neighbor nodes: 1 8 9 12 14 21 23 33 35
2018-01-16 09:58:48.646 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true)
2018-01-16 09:58:48.647 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - checking initialisation queue. Queue size 1.
2018-01-16 09:58:48.647 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - message removed from queue. Queue size 0.
2018-01-16 09:58:48.648 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - NEIGHBORS: queue length(0), free to send(true)
2018-01-16 09:58:48.648 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Initialisation retry timer started 5000
2018-01-16 09:58:48.649 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false)
2018-01-16 09:58:48.649 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer - advancing to DONE
2018-01-16 09:58:48.650 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: loop - DONE try 0: stageAdvanced(true)
2018-01-16 09:58:48.651 [DEBUG] [l.initialization.ZWaveNodeSerializer] - NODE 34: Serializing to file /var/lib/openhab2/zwave/node34.xml
2018-01-16 09:58:48.672 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Node advancer: Initialisation complete!
2018-01-16 09:59:54.198 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 34: Sending REQUEST Message = 01 08 00 13 22 01 00 25 0E EC
2018-01-16 09:59:54.226 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: Sent Data successfully placed on stack.
2018-01-16 09:59:54.284 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: SendData Request. CallBack ID = 14, Status = Transmission complete and ACK received(0)
2018-01-16 09:59:54.286 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Starting initialisation from DONE
2018-01-16 09:59:54.293 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 34: Response processed after 92ms/4245ms.
2018-01-16 09:59:59.262 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 34: Sending REQUEST Message = 01 08 00 13 22 01 00 25 2B C9
2018-01-16 09:59:59.289 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: Sent Data successfully placed on stack.
2018-01-16 09:59:59.343 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: SendData Request. CallBack ID = 43, Status = Transmission complete and ACK received(0)
2018-01-16 09:59:59.344 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Starting initialisation from DONE
2018-01-16 09:59:59.351 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 34: Response processed after 87ms/4245ms.
2018-01-16 09:59:59.357 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 34: Sending REQUEST Message = 01 08 00 13 22 01 00 25 2B C9
2018-01-16 09:59:59.387 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: Sent Data successfully placed on stack.
2018-01-16 09:59:59.453 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 34: SendData Request. CallBack ID = 43, Status = Transmission complete and ACK received(0)
2018-01-16 09:59:59.456 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 34: Starting initialisation from DONE
2018-01-16 09:59:59.476 [DEBUG] [ocol.ZWaveController$ZWaveSendThread] - NODE 34: Response processed after 117ms/4245ms.

sihui · January 16, 2018, 10:37am

This is what I get when feeding your log through the log viewer:

Not sure if something is missing, sorry

smillier · January 16, 2018, 10:45am

So i still can’t understand why it’s unknown by OpenHab.

sihui · January 16, 2018, 10:48am

You are sure you are on a latest binding release?

openhab> bundle:list|grep -i zwave
249 │ Active   │  80 │ 2.2.0.201801021718     │ ZWave Binding

smillier · January 16, 2018, 10:58am

No, that’s strange, i’ve uninstalled it, waited a few minutes and reinstalled.
269 │ Active │ 80 │ 2.3.0.201712272246 │ ZWave Binding
Can I force a reinstall from the console ?

sihui · January 16, 2018, 11:14am

That should do it …

Never tried that, but this should work:

feature:uninstall openhab-binding-zwave

wait …

feature:install openhab-binding-zwave

smillier · January 16, 2018, 12:06pm

I have an error with all commands like feature:uninstall, bundle:update, etc…
openhab> feature:uninstall openhab-binding-zwave
Command not found: feature:uninstall

HomeAutomation · January 16, 2018, 12:17pm

I think the correct command is bundle:uninstall not feature.

smillier · January 16, 2018, 12:25pm

According to Karaf console auto-completion, both seem to be correct. But for me both command give this error, command not found.

HomeAutomation · January 16, 2018, 12:27pm

what does bundle:list says?

smillier · January 16, 2018, 12:29pm

This one is okay, bundle:list gives the list of all installed bundles with their version.

HomeAutomation · January 16, 2018, 12:31pm

try to use bundle:uninstall with number of shown binding instead of bundle name

smillier · January 16, 2018, 12:32pm

Already done it: bundle:uninstall 268 -> command not found

HomeAutomation · January 16, 2018, 12:32pm

strange, no idea, someone from core karaf should take care of this

smillier · January 16, 2018, 1:13pm

I’ll try later with PaperUI, but it’s kind of frustrating not being able to use commands. Again, I’m new to openhab / karaf so I may miss something.

vossivossi · January 16, 2018, 2:15pm

Could you provide a screenshot of the command you enter and the error message?

smillier · January 16, 2018, 2:24pm

2018-01-16_15h23_50

vossivossi · January 16, 2018, 2:34pm

Really strange, the first command for bundle 251 should work, it does for me…
The second will probably not work like this, I think it should be

bundle:uninstall org.openhab.binding.zwave

HomeAutomation · January 16, 2018, 2:52pm

I think the installation of OH is broken, not all karaf commands are supported.