Motion Sensor HSM100 does not show properly in habmin

Avner · October 22, 2016, 6:17pm

Hi,

My motion sensor (hsm100) does not show up properly in habmin.

After disappearing from habmin, I am now seeing the node in habmin (node25 “EZMotion Express Wireless 3 in 1 sensor”) after I doing the following steps:

Added “zwave:masterController = true” (in openhab.cfg)
Plugged out the zwave controller stick (Aeon Labs ZWave ZSTICK-S2) from the openhab machine,
Excluded and re-included directly the zwave stick against the hsm100 device
Plugged back into the openhab machine and restarted openhab.

But the node is grey (no red or green color), and the file node25.xml is missing in ./openhab-1.8.3/etc/zwave/

My questions:

In habmin, what does grey node (no red or green color) indicate?
Who does the inclusion. Should AeonLabs zstick controller do the inclusion first, or is all the inclusion taken care by habmin?
Why etc/zwave/node25.xml is not created?

See below log messages related to node 25

Thanks,
Avner

grep -i "node 25:" logs/zwave.log

2016-10-22 11:04:51.009 [INFO ] [rialApiGetInitDataMessageClass:60  ]- NODE 25: Node found
2016-10-22 11:04:51.016 [DEBUG] [b.z.i.protocol.ZWaveController:512 ]- NODE 25: Init node thread start
2016-10-22 11:04:51.199 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:138 ]- NODE 25: Serializing from file etc/zwave/node25.xml
2016-10-22 11:04:51.199 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:141 ]- NODE 25: Error serializing from file: file does not exist.
2016-10-22 11:04:51.206 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2016-10-22 11:04:51.208 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2016-10-22 11:04:51.208 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:347 ]- NODE 25: Node advancer: Initialisation starting
2016-10-22 11:04:51.208 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to PROTOINFO
2016-10-22 11:04:51.210 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2016-10-22 11:04:51.210 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:356 ]- NODE 25: Node advancer: PROTOINFO - send IdentifyNode
2016-10-22 11:04:51.215 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 25: Node advancer - queued packet. Queue length is 1
2016-10-22 11:04:51.215 [DEBUG] [b.z.i.protocol.ZWaveController:601 ]- NODE 25: Init node thread finished
2016-10-22 11:04:51.252 [DEBUG] [i.p.s.IdentifyNodeMessageClass:56  ]- NODE 25: ProtocolInfo
2016-10-22 11:04:51.252 [DEBUG] [i.p.s.IdentifyNodeMessageClass:72  ]- NODE 25: Listening = false
2016-10-22 11:04:51.252 [DEBUG] [i.p.s.IdentifyNodeMessageClass:73  ]- NODE 25: Routing = true
2016-10-22 11:04:51.253 [DEBUG] [i.p.s.IdentifyNodeMessageClass:74  ]- NODE 25: Beaming = false
2016-10-22 11:04:51.253 [DEBUG] [i.p.s.IdentifyNodeMessageClass:75  ]- NODE 25: Version = 2
2016-10-22 11:04:51.253 [DEBUG] [i.p.s.IdentifyNodeMessageClass:76  ]- NODE 25: FLIRS = false
2016-10-22 11:04:51.253 [DEBUG] [i.p.s.IdentifyNodeMessageClass:77  ]- NODE 25: Security = false
2016-10-22 11:04:51.253 [DEBUG] [i.p.s.IdentifyNodeMessageClass:78  ]- NODE 25: Max Baud = 40000
2016-10-22 11:04:51.253 [DEBUG] [i.p.s.IdentifyNodeMessageClass:94  ]- NODE 25: Basic = Routing Slave
2016-10-22 11:04:51.253 [DEBUG] [i.p.s.IdentifyNodeMessageClass:102 ]- NODE 25: Generic = Multi-Level Sensor
2016-10-22 11:04:51.253 [DEBUG] [i.p.s.IdentifyNodeMessageClass:110 ]- NODE 25: Specific = Routing Multilevel Sensor
2016-10-22 11:04:51.254 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class NO_OPERATION
2016-10-22 11:04:51.254 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class NO_OPERATION to the list of supported command classes.
2016-10-22 11:04:51.254 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class BASIC
2016-10-22 11:04:51.254 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class BASIC to the list of supported command classes.
2016-10-22 11:04:51.254 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class SENSOR_MULTILEVEL
2016-10-22 11:04:51.254 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class SENSOR_MULTILEVEL to the list of supported command classes.
2016-10-22 11:04:51.255 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true)
2016-10-22 11:04:51.255 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 1.
2016-10-22 11:04:51.256 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 0.
2016-10-22 11:04:51.256 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - PROTOINFO: queue length(0), free to send(true)
2016-10-22 11:04:51.256 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false)
2016-10-22 11:04:51.256 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to NEIGHBORS
2016-10-22 11:04:51.256 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true)
2016-10-22 11:04:51.256 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:366 ]- NODE 25: Node advancer: NEIGHBORS - send RoutingInfo
2016-10-22 11:04:51.257 [DEBUG] [p.s.GetRoutingInfoMessageClass:30  ]- NODE 25: Request routing info
2016-10-22 11:04:51.257 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 25: Node advancer - queued packet. Queue length is 1
2016-10-22 11:04:51.359 [DEBUG] [p.s.GetRoutingInfoMessageClass:49  ]- NODE 25: Got NodeRoutingInfo request.
2016-10-22 11:04:51.359 [DEBUG] [p.s.GetRoutingInfoMessageClass:79  ]- NODE 25: Neighbor nodes: 1 14 19
2016-10-22 11:04:51.359 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 25: Notifying event listeners: ZWaveNetworkEvent
2016-10-22 11:04:51.359 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true)
2016-10-22 11:04:51.359 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 1.
2016-10-22 11:04:51.359 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 0.
2016-10-22 11:04:51.360 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - NEIGHBORS: queue length(0), free to send(true)
2016-10-22 11:04:51.360 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false)
2016-10-22 11:04:51.360 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to FAILED_CHECK
2016-10-22 11:04:51.360 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true)
2016-10-22 11:04:51.360 [DEBUG] [i.p.s.IsFailedNodeMessageClass:32  ]- NODE 25: Requesting IsFailedNode status from controller.
2016-10-22 11:04:51.360 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 25: Node advancer - queued packet. Queue length is 1
2016-10-22 11:04:51.466 [DEBUG] [i.p.s.IsFailedNodeMessageClass:56  ]- NODE 25: Is currently marked as healthy by the controller
2016-10-22 11:04:51.466 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true)
2016-10-22 11:04:51.466 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 1.
2016-10-22 11:04:51.466 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 0.
2016-10-22 11:04:51.467 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - FAILED_CHECK: queue length(0), free to send(true)
2016-10-22 11:04:51.467 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false)
2016-10-22 11:04:51.467 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to WAIT
2016-10-22 11:04:51.467 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - WAIT try 0: stageAdvanced(true)
2016-10-22 11:04:51.467 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:390 ]- NODE 25: Node advancer: WAIT - Listening=false, FrequentlyListening=false
2016-10-22 11:04:51.467 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:408 ]- NODE 25: Node advancer: WAIT - Still waiting!
2016-10-22 11:05:51.815 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1102]- NODE 25: Node advancer - WAIT: The WAIT is over!
2016-10-22 11:05:51.815 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 0.

chris · October 22, 2016, 6:29pm

It means the node isn’t initialised.

Either is fine - it doesn’t matter. If it’s done by the stick, the binding will read all the nodes the next time the binding starts.

It means the node isn’t initialised.

???

I would suggest not to use 1.8.3 - please update the binding to 1.9 snapshot as 1.8.3 has a problem with the database.

Avner · October 22, 2016, 6:34pm

Sorry Chris. It took me a while to figure how to post the code snippet in code block. I just added it to the original post.

chris · October 22, 2016, 6:37pm

No probs…

So, from the log there is no communication between the device and the controller. All the communication is between the binding and the controller.

Since this is a battery device, you will need to wake it up manually, or if the device has been initialised in the past then just wait for it to wake automatically.

Avner · October 22, 2016, 6:43pm

When I installed openhab it was from source (from Releases · openhab/openhab1-addons · GitHub)

The binding that I’m using are:

ll addons/
org.openhab.binding.http-1.8.3.jar
org.openhab.binding.ntp-1.8.3.jar
org.openhab.binding.zwave-1.9.0-SNAPSHOT.jar
org.openhab.io.habmin-1.5.0-SNAPSHOT.jar
org.openhab.io.myopenhab-1.8.2.jar
org.openhab.persistence.exec-1.8.3.jar
org.openhab.persistence.logging-1.8.3.jar
org.openhab.persistence.rrd4j-1.8.3.jar

Should I update a specific binding to 1.9 or upgrade the entire openhab from 1.8.3 to 1.9 (how do I do that?)

chris · October 22, 2016, 6:44pm

It’s ok - you have the 1.9 binding, so this shouldn’t be a problem. I suspect the issue is just that the device needs to wake up…

Avner · October 22, 2016, 7:28pm

The hsm100 documentation (http://www.expresscontrols.com/pdf/EZMotion+OwnerManual.pdf) says:
…
Pressing the blue reset button will restart the 10 minute full-power mode if additional time is
needed to configure EZMotion+.
…
As I understand, this is waking up the device.

I did the following:

pressed the button (at this point I assume that the device is awake?)
changed in habmin node 25 (node 25 -> Wakeup period -> Wakeup interval -> 600 (10 min?))
set Assocoation Groups -> Association Group -> Node 1 -> Memeber

In habmin the node is still grey
etc/zwave/node25.xml is still not created

After restarting openhab I checked again:

habmin shows node25 without "EZMotion Express Wireless 3 in 1 sensor"
I have to press the button on the hsm100 again and before seeing node25 with “EZMotion Express Wireless 3 in 1 sensor”
Assocoation Groups -> Association Group -> Node 1 shows as Non-Memeber (the change didn’t stick)
Wakeup period -> Wakeup interval shows 3600 (the change didn’t stick)

Here are the messages After resatrting openhab and before pressing the button on hsm100

2016-10-22 12:08:34.534 [INFO ] [rialApiGetInitDataMessageClass:60  ]- NODE 25: Node found
2016-10-22 12:08:34.543 [DEBUG] [b.z.i.protocol.ZWaveController:512 ]- NODE 25: Init node thread start
2016-10-22 12:08:34.793 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:138 ]- NODE 25: Serializing from file etc/zwave/node25.xml
2016-10-22 12:08:34.794 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:141 ]- NODE 25: Error serializing from file: file does not exist.
2016-10-22 12:08:34.802 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - EMPTYNODE: queue length(0), free to send(true)
2016-10-22 12:08:34.803 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false)
2016-10-22 12:08:34.812 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:347 ]- NODE 25: Node advancer: Initialisation starting
2016-10-22 12:08:34.813 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to PROTOINFO
2016-10-22 12:08:34.813 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true)
2016-10-22 12:08:34.814 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:356 ]- NODE 25: Node advancer: PROTOINFO - send IdentifyNode
2016-10-22 12:08:34.815 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 25: Node advancer - queued packet. Queue length is 1
2016-10-22 12:08:34.815 [DEBUG] [b.z.i.protocol.ZWaveController:601 ]- NODE 25: Init node thread finished
2016-10-22 12:08:34.875 [DEBUG] [i.p.s.IdentifyNodeMessageClass:56  ]- NODE 25: ProtocolInfo
2016-10-22 12:08:34.875 [DEBUG] [i.p.s.IdentifyNodeMessageClass:72  ]- NODE 25: Listening = false
2016-10-22 12:08:34.875 [DEBUG] [i.p.s.IdentifyNodeMessageClass:73  ]- NODE 25: Routing = true
2016-10-22 12:08:34.875 [DEBUG] [i.p.s.IdentifyNodeMessageClass:74  ]- NODE 25: Beaming = false
2016-10-22 12:08:34.875 [DEBUG] [i.p.s.IdentifyNodeMessageClass:75  ]- NODE 25: Version = 2
2016-10-22 12:08:34.875 [DEBUG] [i.p.s.IdentifyNodeMessageClass:76  ]- NODE 25: FLIRS = false
2016-10-22 12:08:34.875 [DEBUG] [i.p.s.IdentifyNodeMessageClass:77  ]- NODE 25: Security = false
2016-10-22 12:08:34.875 [DEBUG] [i.p.s.IdentifyNodeMessageClass:78  ]- NODE 25: Max Baud = 40000
2016-10-22 12:08:34.875 [DEBUG] [i.p.s.IdentifyNodeMessageClass:94  ]- NODE 25: Basic = Routing Slave
2016-10-22 12:08:34.875 [DEBUG] [i.p.s.IdentifyNodeMessageClass:102 ]- NODE 25: Generic = Multi-Level Sensor
2016-10-22 12:08:34.875 [DEBUG] [i.p.s.IdentifyNodeMessageClass:110 ]- NODE 25: Specific = Routing Multilevel Sensor
2016-10-22 12:08:34.875 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class NO_OPERATION
2016-10-22 12:08:34.875 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class NO_OPERATION to the list of supported command classes.
2016-10-22 12:08:34.875 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class BASIC
2016-10-22 12:08:34.875 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class BASIC to the list of supported command classes.
2016-10-22 12:08:34.875 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class SENSOR_MULTILEVEL
2016-10-22 12:08:34.875 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class SENSOR_MULTILEVEL to the list of supported command classes.
2016-10-22 12:08:34.876 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true)
2016-10-22 12:08:34.876 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 1.
2016-10-22 12:08:34.876 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 0.
2016-10-22 12:08:34.876 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - PROTOINFO: queue length(0), free to send(true)
2016-10-22 12:08:34.876 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false)
2016-10-22 12:08:34.877 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to NEIGHBORS
2016-10-22 12:08:34.877 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true)
2016-10-22 12:08:34.877 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:366 ]- NODE 25: Node advancer: NEIGHBORS - send RoutingInfo
2016-10-22 12:08:34.877 [DEBUG] [p.s.GetRoutingInfoMessageClass:30  ]- NODE 25: Request routing info
2016-10-22 12:08:34.877 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 25: Node advancer - queued packet. Queue length is 1
2016-10-22 12:08:34.996 [DEBUG] [p.s.GetRoutingInfoMessageClass:49  ]- NODE 25: Got NodeRoutingInfo request.
2016-10-22 12:08:34.996 [DEBUG] [p.s.GetRoutingInfoMessageClass:79  ]- NODE 25: Neighbor nodes: 1 14 19
2016-10-22 12:08:34.996 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 25: Notifying event listeners: ZWaveNetworkEvent
2016-10-22 12:08:34.997 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true)
2016-10-22 12:08:34.997 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 1.
2016-10-22 12:08:34.997 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 0.
2016-10-22 12:08:34.997 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - NEIGHBORS: queue length(0), free to send(true)
2016-10-22 12:08:34.997 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false)
2016-10-22 12:08:34.998 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to FAILED_CHECK
2016-10-22 12:08:34.998 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true)
2016-10-22 12:08:34.998 [DEBUG] [i.p.s.IsFailedNodeMessageClass:32  ]- NODE 25: Requesting IsFailedNode status from controller.
2016-10-22 12:08:34.998 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 25: Node advancer - queued packet. Queue length is 1
2016-10-22 12:08:35.019 [DEBUG] [.z.internal.ZWaveActiveBinding:194 ]- NODE 25: Polling list: item Motion_gAllFloors is not completed initialisation
2016-10-22 12:08:35.019 [DEBUG] [.z.internal.ZWaveActiveBinding:194 ]- NODE 25: Polling list: item Temperature_gAllFloors is not completed initialisation
2016-10-22 12:08:35.088 [DEBUG] [i.p.s.IsFailedNodeMessageClass:56  ]- NODE 25: Is currently marked as healthy by the controller
2016-10-22 12:08:35.088 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true)
2016-10-22 12:08:35.088 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 1.
2016-10-22 12:08:35.088 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 0.
2016-10-22 12:08:35.089 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - FAILED_CHECK: queue length(0), free to send(true)
2016-10-22 12:08:35.089 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false)
2016-10-22 12:08:35.089 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to WAIT
2016-10-22 12:08:35.089 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - WAIT try 0: stageAdvanced(true)
2016-10-22 12:08:35.089 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:390 ]- NODE 25: Node advancer: WAIT - Listening=false, FrequentlyListening=false
2016-10-22 12:08:35.089 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:408 ]- NODE 25: Node advancer: WAIT - Still waiting!

Avner · October 22, 2016, 7:31pm

And here are the messages after resatrting openhab and after pressing the button on hsm100 (part1 of 3)

2016-10-22 12:10:46.028 [DEBUG] [.ApplicationUpdateMessageClass:49  ]- NODE 25: Application update request. Node information received.
2016-10-22 12:10:46.029 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MULTI_INSTANCE
2016-10-22 12:10:46.029 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class MULTI_INSTANCE to the list of supported command classes.
2016-10-22 12:10:46.029 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class CONFIGURATION
2016-10-22 12:10:46.029 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class CONFIGURATION to the list of supported command classes.
2016-10-22 12:10:46.029 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class WAKE_UP
2016-10-22 12:10:46.030 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class WAKE_UP to the list of supported command classes.
2016-10-22 12:10:46.030 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class ASSOCIATION
2016-10-22 12:10:46.030 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class ASSOCIATION to the list of supported command classes.
2016-10-22 12:10:46.031 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class BATTERY
2016-10-22 12:10:46.031 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class BATTERY to the list of supported command classes.
2016-10-22 12:10:46.031 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MANUFACTURER_SPECIFIC
2016-10-22 12:10:46.031 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class MANUFACTURER_SPECIFIC to the list of supported command classes.
2016-10-22 12:10:46.031 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class NODE_NAMING
2016-10-22 12:10:46.031 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class NODE_NAMING to the list of supported command classes.
2016-10-22 12:10:46.032 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class VERSION
2016-10-22 12:10:46.032 [DEBUG] [.z.internal.protocol.ZWaveNode:614 ]- NODE 25: Adding command class VERSION to the list of supported command classes.
2016-10-22 12:10:46.032 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 25: Notifying event listeners: ZWaveNodeInfoEvent
2016-10-22 12:10:46.032 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 25: 18 NIF event during initialisation stage PING
2016-10-22 12:10:46.032 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 25: 17 NIF event during initialisation stage DETAILS
2016-10-22 12:10:46.032 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 25: 16 NIF event during initialisation stage PING
2016-10-22 12:10:46.032 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 25: 25 NIF event during initialisation stage WAIT
2016-10-22 12:10:46.033 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1174]- NODE 25: NIF event during initialisation stage WAIT
2016-10-22 12:10:46.033 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - WAIT: queue length(0), free to send(true)
2016-10-22 12:10:46.033 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - WAIT try 1: stageAdvanced(false)
2016-10-22 12:10:46.033 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:390 ]- NODE 25: Node advancer: WAIT - Listening=false, FrequentlyListening=false
2016-10-22 12:10:46.033 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:408 ]- NODE 25: Node advancer: WAIT - Still waiting!
2016-10-22 12:10:46.033 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 25: 9 NIF event during initialisation stage WAIT
2016-10-22 12:10:46.033 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 25: 13 NIF event during initialisation stage PING
2016-10-22 12:10:46.033 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 25: 14 NIF event during initialisation stage PING
2016-10-22 12:10:46.033 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 25: 19 NIF event during initialisation stage PING
2016-10-22 12:10:46.034 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 25: 21 NIF event during initialisation stage DYNAMIC_VALUES
2016-10-22 12:10:46.034 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 25: 22 NIF event during initialisation stage DYNAMIC_VALUES
2016-10-22 12:10:46.034 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:449 ]- NODE 25: Is awake with 0 messages in the wake-up queue.
2016-10-22 12:10:46.034 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 25: Notifying event listeners: ZWaveWakeUpEvent
2016-10-22 12:10:46.035 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1140]- NODE 25: Wakeup during initialisation.
2016-10-22 12:10:46.035 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - WAIT: queue length(0), free to send(true)
2016-10-22 12:10:46.035 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - WAIT try 2: stageAdvanced(false)
2016-10-22 12:10:46.035 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:390 ]- NODE 25: Node advancer: WAIT - Listening=false, FrequentlyListening=false
2016-10-22 12:10:46.035 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:402 ]- NODE 25: Node advancer: WAIT - Node is awake
2016-10-22 12:10:46.035 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to PING
2016-10-22 12:10:46.035 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - PING try 0: stageAdvanced(true)
2016-10-22 12:10:46.035 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:427 ]- NODE 25: Node advancer: PING - send NoOperation
2016-10-22 12:10:46.036 [DEBUG] [c.ZWaveNoOperationCommandClass:72  ]- NODE 25: Creating new message for command No Operation
2016-10-22 12:10:46.036 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:46.036 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 25: Node advancer - queued packet. Queue length is 1
2016-10-22 12:10:46.040 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 25: Sending REQUEST Message = 01 08 00 13 19 01 00 25 2B F2 
2016-10-22 12:10:46.045 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 25: Sent Data successfully placed on stack.
2016-10-22 12:10:47.315 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 25: SendData Request. CallBack ID = 43, Status = Transmission complete and ACK received(0)
2016-10-22 12:10:47.316 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 25: Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-22 12:10:47.316 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - PING: Transaction complete (SendData:Request) success(true)
2016-10-22 12:10:47.316 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 1.
2016-10-22 12:10:47.316 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 0.
2016-10-22 12:10:47.316 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - PING: queue length(0), free to send(true)
2016-10-22 12:10:47.316 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - PING try 1: stageAdvanced(false)
2016-10-22 12:10:47.317 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to SECURITY_REPORT
2016-10-22 12:10:47.317 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - SECURITY_REPORT try 0: stageAdvanced(true)
2016-10-22 12:10:47.317 [INFO ] [z.i.p.i.ZWaveNodeStageAdvancer:509 ]- NODE 25: does not support SECURITY_REPORT, proceeding to next stage.
2016-10-22 12:10:47.317 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to DETAILS
2016-10-22 12:10:47.317 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - DETAILS try 0: stageAdvanced(true)
2016-10-22 12:10:47.317 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:525 ]- NODE 25: Node advancer: received RequestNodeInfo
2016-10-22 12:10:47.317 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to MANUFACTURER
2016-10-22 12:10:47.317 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - MANUFACTURER try 0: stageAdvanced(true)
2016-10-22 12:10:47.318 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:547 ]- NODE 25: Node advancer: MANUFACTURER - send ManufacturerSpecific
2016-10-22 12:10:47.318 [DEBUG] [nufacturerSpecificCommandClass:105 ]- NODE 25: Creating new message for command MANUFACTURER_SPECIFIC_GET
2016-10-22 12:10:47.318 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.318 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 25: Node advancer - queued packet. Queue length is 1
2016-10-22 12:10:47.319 [DEBUG] [WaveController$ZWaveSendThread:1430]- NODE 25: Response processed for callback id 43 after 1279ms/2082ms.
2016-10-22 12:10:47.319 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 25: Sending REQUEST Message = 01 09 00 13 19 02 72 04 25 2D 80 
2016-10-22 12:10:47.326 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 25: Sent Data successfully placed on stack.
2016-10-22 12:10:47.337 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 25: SendData Request. CallBack ID = 45, Status = Transmission complete and ACK received(0)
2016-10-22 12:10:47.347 [DEBUG] [ApplicationCommandMessageClass:41  ]- NODE 25: Application Command Request (ALIVE:MANUFACTURER)
2016-10-22 12:10:47.347 [DEBUG] [ApplicationCommandMessageClass:146 ]- NODE 25: Incoming command class MANUFACTURER_SPECIFIC (0x72)
2016-10-22 12:10:47.348 [DEBUG] [nufacturerSpecificCommandClass:65  ]- NODE 25: Received Manufacture Specific Information
2016-10-22 12:10:47.348 [DEBUG] [nufacturerSpecificCommandClass:85  ]- NODE 25: Manufacturer ID = 0x001e
2016-10-22 12:10:47.348 [DEBUG] [nufacturerSpecificCommandClass:87  ]- NODE 25: Device Type = 0x0002
2016-10-22 12:10:47.349 [DEBUG] [nufacturerSpecificCommandClass:89  ]- NODE 25: Device ID = 0x0001
2016-10-22 12:10:47.350 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 25: Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-22 12:10:47.350 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - MANUFACTURER: Transaction complete (SendData:Request) success(true)
2016-10-22 12:10:47.350 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 1.
2016-10-22 12:10:47.350 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 0.
2016-10-22 12:10:47.350 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - MANUFACTURER: queue length(0), free to send(true)
2016-10-22 12:10:47.350 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - MANUFACTURER try 1: stageAdvanced(false)
2016-10-22 12:10:47.350 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to VERSION
2016-10-22 12:10:47.351 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - VERSION try 0: stageAdvanced(true)
2016-10-22 12:10:47.351 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking SENSOR_MULTILEVEL, version is 0
2016-10-22 12:10:47.351 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:565 ]- NODE 25: Node advancer: VERSION - queued   SENSOR_MULTILEVEL
2016-10-22 12:10:47.351 [DEBUG] [i.p.c.ZWaveVersionCommandClass:176 ]- NODE 25: Creating new message for application command VERSION_COMMAND_CLASS_GET command class SENSOR_MULTILEVEL
2016-10-22 12:10:47.351 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.351 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking CONFIGURATION, version is 0
2016-10-22 12:10:47.352 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:569 ]- NODE 25: Node advancer: VERSION - VERSION default to 1
2016-10-22 12:10:47.352 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking ASSOCIATION, version is 0
2016-10-22 12:10:47.352 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:569 ]- NODE 25: Node advancer: VERSION - VERSION default to 1
2016-10-22 12:10:47.352 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking NODE_NAMING, version is 0
2016-10-22 12:10:47.352 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:569 ]- NODE 25: Node advancer: VERSION - VERSION default to 1
2016-10-22 12:10:47.352 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking VERSION, version is 0
2016-10-22 12:10:47.352 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:569 ]- NODE 25: Node advancer: VERSION - VERSION default to 1
2016-10-22 12:10:47.352 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking MANUFACTURER_SPECIFIC, version is 0
2016-10-22 12:10:47.352 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:569 ]- NODE 25: Node advancer: VERSION - VERSION default to 1
2016-10-22 12:10:47.353 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking NO_OPERATION, version is 0
2016-10-22 12:10:47.353 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:569 ]- NODE 25: Node advancer: VERSION - VERSION default to 1
2016-10-22 12:10:47.353 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking BASIC, version is 0
2016-10-22 12:10:47.353 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:569 ]- NODE 25: Node advancer: VERSION - VERSION default to 1
2016-10-22 12:10:47.353 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking WAKE_UP, version is 0
2016-10-22 12:10:47.353 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:565 ]- NODE 25: Node advancer: VERSION - queued   WAKE_UP
2016-10-22 12:10:47.353 [DEBUG] [i.p.c.ZWaveVersionCommandClass:176 ]- NODE 25: Creating new message for application command VERSION_COMMAND_CLASS_GET command class WAKE_UP
2016-10-22 12:10:47.353 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.353 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking BATTERY, version is 0
2016-10-22 12:10:47.354 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:569 ]- NODE 25: Node advancer: VERSION - VERSION default to 1
2016-10-22 12:10:47.354 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking MULTI_INSTANCE, version is 0
2016-10-22 12:10:47.354 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:565 ]- NODE 25: Node advancer: VERSION - queued   MULTI_INSTANCE
2016-10-22 12:10:47.354 [DEBUG] [i.p.c.ZWaveVersionCommandClass:176 ]- NODE 25: Creating new message for application command VERSION_COMMAND_CLASS_GET command class MULTI_INSTANCE
2016-10-22 12:10:47.354 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.354 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:573 ]- NODE 25: Node advancer: VERSION - queued 3 frames
2016-10-22 12:10:47.354 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 25: Node advancer - queued packet. Queue length is 3
2016-10-22 12:10:47.355 [DEBUG] [WaveController$ZWaveSendThread:1430]- NODE 25: Response processed for callback id 45 after 36ms/2082ms.
2016-10-22 12:10:47.355 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 25: Sending REQUEST Message = 01 0A 00 13 19 03 86 13 31 25 2E 53 
2016-10-22 12:10:47.370 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 25: Sent Data successfully placed on stack.
2016-10-22 12:10:47.374 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 25: SendData Request. CallBack ID = 46, Status = Transmission complete and ACK received(0)
2016-10-22 12:10:47.382 [DEBUG] [ApplicationCommandMessageClass:41  ]- NODE 25: Application Command Request (ALIVE:VERSION)
2016-10-22 12:10:47.382 [DEBUG] [ApplicationCommandMessageClass:146 ]- NODE 25: Incoming command class VERSION (0x86)
2016-10-22 12:10:47.382 [DEBUG] [i.p.c.ZWaveVersionCommandClass:77  ]- NODE 25: Received Version Request
2016-10-22 12:10:47.382 [DEBUG] [i.p.c.ZWaveVersionCommandClass:98  ]- NODE 25: Process Version Command Class Report
2016-10-22 12:10:47.383 [DEBUG] [i.p.c.ZWaveVersionCommandClass:109 ]- NODE 25: Requested Command Class = SENSOR_MULTILEVEL, Version = 1
2016-10-22 12:10:47.383 [DEBUG] [i.p.c.ZWaveVersionCommandClass:142 ]- NODE 25: Version = 1, version set. Enabling extra functionality.
2016-10-22 12:10:47.383 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 25: Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-22 12:10:47.384 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - VERSION: Transaction complete (SendData:Request) success(true)
2016-10-22 12:10:47.384 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 3.
2016-10-22 12:10:47.384 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 2.
2016-10-22 12:10:47.384 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - VERSION: queue length(2), free to send(true)
2016-10-22 12:10:47.384 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 25: Node advancer - queued packet. Queue length is 2
2016-10-22 12:10:47.384 [DEBUG] [WaveController$ZWaveSendThread:1430]- NODE 25: Response processed for callback id 46 after 29ms/2082ms.
2016-10-22 12:10:47.385 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 25: Sending REQUEST Message = 01 0A 00 13 19 03 86 13 84 25 2F E7 
2016-10-22 12:10:47.391 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 25: Sent Data successfully placed on stack.
2016-10-22 12:10:47.404 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 25: SendData Request. CallBack ID = 47, Status = Transmission complete and ACK received(0)
2016-10-22 12:10:47.411 [DEBUG] [ApplicationCommandMessageClass:41  ]- NODE 25: Application Command Request (ALIVE:VERSION)
2016-10-22 12:10:47.411 [DEBUG] [ApplicationCommandMessageClass:146 ]- NODE 25: Incoming command class VERSION (0x86)
2016-10-22 12:10:47.412 [DEBUG] [i.p.c.ZWaveVersionCommandClass:77  ]- NODE 25: Received Version Request
2016-10-22 12:10:47.412 [DEBUG] [i.p.c.ZWaveVersionCommandClass:98  ]- NODE 25: Process Version Command Class Report
2016-10-22 12:10:47.412 [DEBUG] [i.p.c.ZWaveVersionCommandClass:109 ]- NODE 25: Requested Command Class = WAKE_UP, Version = 2
2016-10-22 12:10:47.412 [DEBUG] [i.p.c.ZWaveVersionCommandClass:142 ]- NODE 25: Version = 2, version set. Enabling extra functionality.
2016-10-22 12:10:47.413 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 25: Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-22 12:10:47.413 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - VERSION: Transaction complete (SendData:Request) success(true)
2016-10-22 12:10:47.413 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 2.
2016-10-22 12:10:47.413 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 1.
2016-10-22 12:10:47.413 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - VERSION: queue length(1), free to send(true)
2016-10-22 12:10:47.414 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 25: Node advancer - queued packet. Queue length is 1
2016-10-22 12:10:47.414 [DEBUG] [WaveController$ZWaveSendThread:1430]- NODE 25: Response processed for callback id 47 after 29ms/2082ms.
2016-10-22 12:10:47.414 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 25: Sending REQUEST Message = 01 0A 00 13 19 03 86 13 60 25 30 1C 
2016-10-22 12:10:47.421 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 25: Sent Data successfully placed on stack.
2016-10-22 12:10:47.433 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 25: SendData Request. CallBack ID = 48, Status = Transmission complete and ACK received(0)
2016-10-22 12:10:47.441 [DEBUG] [ApplicationCommandMessageClass:41  ]- NODE 25: Application Command Request (ALIVE:VERSION)
2016-10-22 12:10:47.441 [DEBUG] [ApplicationCommandMessageClass:146 ]- NODE 25: Incoming command class VERSION (0x86)
2016-10-22 12:10:47.441 [DEBUG] [i.p.c.ZWaveVersionCommandClass:77  ]- NODE 25: Received Version Request
2016-10-22 12:10:47.442 [DEBUG] [i.p.c.ZWaveVersionCommandClass:98  ]- NODE 25: Process Version Command Class Report
2016-10-22 12:10:47.442 [DEBUG] [i.p.c.ZWaveVersionCommandClass:109 ]- NODE 25: Requested Command Class = MULTI_INSTANCE, Version = 2
2016-10-22 12:10:47.442 [DEBUG] [i.p.c.ZWaveVersionCommandClass:142 ]- NODE 25: Version = 2, version set. Enabling extra functionality.
2016-10-22 12:10:47.443 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 25: Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-22 12:10:47.443 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - VERSION: Transaction complete (SendData:Request) success(true)
2016-10-22 12:10:47.443 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 1.
2016-10-22 12:10:47.443 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 0.
2016-10-22 12:10:47.443 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - VERSION: queue length(0), free to send(true)
2016-10-22 12:10:47.443 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - VERSION try 1: stageAdvanced(false)
2016-10-22 12:10:47.443 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking SENSOR_MULTILEVEL, version is 1
2016-10-22 12:10:47.443 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking CONFIGURATION, version is 1
2016-10-22 12:10:47.443 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking ASSOCIATION, version is 1
2016-10-22 12:10:47.444 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking NODE_NAMING, version is 1
2016-10-22 12:10:47.444 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking VERSION, version is 1
2016-10-22 12:10:47.444 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking MANUFACTURER_SPECIFIC, version is 1
2016-10-22 12:10:47.444 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking NO_OPERATION, version is 1
2016-10-22 12:10:47.444 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking BASIC, version is 1
2016-10-22 12:10:47.444 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking WAKE_UP, version is 2
2016-10-22 12:10:47.444 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking BATTERY, version is 1
2016-10-22 12:10:47.444 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:561 ]- NODE 25: Node advancer: VERSION - checking MULTI_INSTANCE, version is 2
2016-10-22 12:10:47.444 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:573 ]- NODE 25: Node advancer: VERSION - queued 0 frames
2016-10-22 12:10:47.444 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to APP_VERSION
2016-10-22 12:10:47.445 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - APP_VERSION try 0: stageAdvanced(true)
2016-10-22 12:10:47.445 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:592 ]- NODE 25: Node advancer: APP_VERSION - send VersionMessage
2016-10-22 12:10:47.445 [DEBUG] [i.p.c.ZWaveVersionCommandClass:158 ]- NODE 25: Creating new message for command VERSION_GET
2016-10-22 12:10:47.445 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.445 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 25: Node advancer - queued packet. Queue length is 1
2016-10-22 12:10:47.446 [DEBUG] [WaveController$ZWaveSendThread:1430]- NODE 25: Response processed for callback id 48 after 32ms/2082ms.
2016-10-22 12:10:47.446 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 25: Sending REQUEST Message = 01 09 00 13 19 02 86 11 25 31 7D 
2016-10-22 12:10:47.452 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 25: Sent Data successfully placed on stack.
2016-10-22 12:10:47.465 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 25: SendData Request. CallBack ID = 49, Status = Transmission complete and ACK received(0)

Avner · October 22, 2016, 7:32pm

And here are the messages after resatrting openhab and after pressing the button on hsm100 (part2)

2016-10-22 12:10:47.474 [DEBUG] [ApplicationCommandMessageClass:41  ]- NODE 25: Application Command Request (ALIVE:APP_VERSION)
2016-10-22 12:10:47.474 [DEBUG] [ApplicationCommandMessageClass:146 ]- NODE 25: Incoming command class VERSION (0x86)
2016-10-22 12:10:47.474 [DEBUG] [i.p.c.ZWaveVersionCommandClass:77  ]- NODE 25: Received Version Request
2016-10-22 12:10:47.474 [DEBUG] [i.p.c.ZWaveVersionCommandClass:85  ]- NODE 25: Process Version Report
2016-10-22 12:10:47.474 [DEBUG] [i.p.c.ZWaveVersionCommandClass:92  ]- NODE 25: Library Type        = 6 (Routing Slave)
2016-10-22 12:10:47.474 [DEBUG] [i.p.c.ZWaveVersionCommandClass:94  ]- NODE 25: Protocol Version    = 2.40
2016-10-22 12:10:47.474 [DEBUG] [i.p.c.ZWaveVersionCommandClass:95  ]- NODE 25: Application Version = 1.12
2016-10-22 12:10:47.475 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 25: Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-22 12:10:47.475 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - APP_VERSION: Transaction complete (SendData:Request) success(true)
2016-10-22 12:10:47.475 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 1.
2016-10-22 12:10:47.476 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 0.
2016-10-22 12:10:47.476 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - APP_VERSION: queue length(0), free to send(true)
2016-10-22 12:10:47.476 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - APP_VERSION try 1: stageAdvanced(false)
2016-10-22 12:10:47.476 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to ENDPOINTS
2016-10-22 12:10:47.476 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - ENDPOINTS try 0: stageAdvanced(true)
2016-10-22 12:10:47.476 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:602 ]- NODE 25: Node advancer: ENDPOINTS - MultiInstance is supported
2016-10-22 12:10:47.476 [DEBUG] [ZWaveMultiInstanceCommandClass:614 ]- NODE 25: Initialising endpoints - version 2
2016-10-22 12:10:47.476 [DEBUG] [ZWaveMultiInstanceCommandClass:551 ]- NODE 25: Creating new message for command MULTI_CHANNEL_ENDPOINT_GET
2016-10-22 12:10:47.477 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.477 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:605 ]- NODE 25: Node advancer: ENDPOINTS - queued 1 frames
2016-10-22 12:10:47.477 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 25: Node advancer - queued packet. Queue length is 1
2016-10-22 12:10:47.477 [DEBUG] [WaveController$ZWaveSendThread:1430]- NODE 25: Response processed for callback id 49 after 31ms/2082ms.
2016-10-22 12:10:47.478 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 25: Sending REQUEST Message = 01 09 00 13 19 02 60 07 25 32 8E 
2016-10-22 12:10:47.484 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 25: Sent Data successfully placed on stack.
2016-10-22 12:10:47.496 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 25: SendData Request. CallBack ID = 50, Status = Transmission complete and ACK received(0)
2016-10-22 12:10:47.504 [DEBUG] [ApplicationCommandMessageClass:41  ]- NODE 25: Application Command Request (ALIVE:ENDPOINTS)
2016-10-22 12:10:47.504 [DEBUG] [ApplicationCommandMessageClass:146 ]- NODE 25: Incoming command class MULTI_INSTANCE (0x60)
2016-10-22 12:10:47.504 [DEBUG] [ZWaveMultiInstanceCommandClass:138 ]- NODE 25: Received Multi-instance/Multi-channel Request
2016-10-22 12:10:47.504 [DEBUG] [ZWaveMultiInstanceCommandClass:278 ]- NODE 25: Changing number of endpoints = false
2016-10-22 12:10:47.504 [DEBUG] [ZWaveMultiInstanceCommandClass:280 ]- NODE 25: Endpoints are the same device class = true
2016-10-22 12:10:47.504 [DEBUG] [ZWaveMultiInstanceCommandClass:282 ]- NODE 25: Number of endpoints = 3
2016-10-22 12:10:47.505 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 25: Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-22 12:10:47.505 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - ENDPOINTS: Transaction complete (SendData:Request) success(true)
2016-10-22 12:10:47.505 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 1.
2016-10-22 12:10:47.506 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 0.
2016-10-22 12:10:47.506 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - ENDPOINTS: queue length(0), free to send(true)
2016-10-22 12:10:47.506 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - ENDPOINTS try 1: stageAdvanced(false)
2016-10-22 12:10:47.506 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:602 ]- NODE 25: Node advancer: ENDPOINTS - MultiInstance is supported
2016-10-22 12:10:47.506 [DEBUG] [ZWaveMultiInstanceCommandClass:614 ]- NODE 25: Initialising endpoints - version 2
2016-10-22 12:10:47.506 [DEBUG] [ZWaveMultiInstanceCommandClass:569 ]- NODE 25: Creating new message for command MULTI_CHANNEL_CAPABILITY_GET endpoint 1
2016-10-22 12:10:47.506 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.506 [DEBUG] [ZWaveMultiInstanceCommandClass:569 ]- NODE 25: Creating new message for command MULTI_CHANNEL_CAPABILITY_GET endpoint 2
2016-10-22 12:10:47.506 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.507 [DEBUG] [ZWaveMultiInstanceCommandClass:569 ]- NODE 25: Creating new message for command MULTI_CHANNEL_CAPABILITY_GET endpoint 3
2016-10-22 12:10:47.507 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.507 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:605 ]- NODE 25: Node advancer: ENDPOINTS - queued 3 frames
2016-10-22 12:10:47.507 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 25: Node advancer - queued packet. Queue length is 3
2016-10-22 12:10:47.507 [DEBUG] [WaveController$ZWaveSendThread:1430]- NODE 25: Response processed for callback id 50 after 29ms/2082ms.
2016-10-22 12:10:47.508 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 25: Sending REQUEST Message = 01 0A 00 13 19 03 60 09 01 25 33 82 
2016-10-22 12:10:47.514 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 25: Sent Data successfully placed on stack.
2016-10-22 12:10:47.527 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 25: SendData Request. CallBack ID = 51, Status = Transmission complete and ACK received(0)
2016-10-22 12:10:47.539 [DEBUG] [ApplicationCommandMessageClass:41  ]- NODE 25: Application Command Request (ALIVE:ENDPOINTS)
2016-10-22 12:10:47.539 [DEBUG] [ApplicationCommandMessageClass:146 ]- NODE 25: Incoming command class MULTI_INSTANCE (0x60)
2016-10-22 12:10:47.539 [DEBUG] [ZWaveMultiInstanceCommandClass:138 ]- NODE 25: Received Multi-instance/Multi-channel Request
2016-10-22 12:10:47.540 [DEBUG] [ZWaveMultiInstanceCommandClass:307 ]- NODE 25: Process Multi-channel capability Report
2016-10-22 12:10:47.540 [DEBUG] [ZWaveMultiInstanceCommandClass:313 ]- NODE 25: Endpoints are the same device class = true
2016-10-22 12:10:47.540 [DEBUG] [ZWaveMultiInstanceCommandClass:386 ]- NODE 25: Endpoint Id = 1
2016-10-22 12:10:47.540 [DEBUG] [ZWaveMultiInstanceCommandClass:387 ]- NODE 25: Endpoints is dynamic = false
2016-10-22 12:10:47.540 [DEBUG] [ZWaveMultiInstanceCommandClass:388 ]- NODE 25: Basic = Routing Slave 0x04
2016-10-22 12:10:47.541 [DEBUG] [ZWaveMultiInstanceCommandClass:390 ]- NODE 25: Generic = Multi-Level Sensor 0x21
2016-10-22 12:10:47.541 [DEBUG] [ZWaveMultiInstanceCommandClass:392 ]- NODE 25: Specific = Routing Multilevel Sensor 0x01
2016-10-22 12:10:47.541 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MULTI_INSTANCE
2016-10-22 12:10:47.541 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class MULTI_INSTANCE.
2016-10-22 12:10:47.541 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class SENSOR_MULTILEVEL
2016-10-22 12:10:47.542 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class SENSOR_MULTILEVEL.
2016-10-22 12:10:47.542 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class CONFIGURATION
2016-10-22 12:10:47.542 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class CONFIGURATION.
2016-10-22 12:10:47.542 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class WAKE_UP
2016-10-22 12:10:47.542 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class WAKE_UP.
2016-10-22 12:10:47.543 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class ASSOCIATION
2016-10-22 12:10:47.543 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class ASSOCIATION.
2016-10-22 12:10:47.543 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class BATTERY
2016-10-22 12:10:47.543 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class BATTERY.
2016-10-22 12:10:47.543 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MANUFACTURER_SPECIFIC
2016-10-22 12:10:47.543 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class MANUFACTURER_SPECIFIC.
2016-10-22 12:10:47.543 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class NODE_NAMING
2016-10-22 12:10:47.543 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class NODE_NAMING.
2016-10-22 12:10:47.544 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class VERSION
2016-10-22 12:10:47.544 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class VERSION.
2016-10-22 12:10:47.544 [DEBUG] [ZWaveMultiInstanceCommandClass:386 ]- NODE 25: Endpoint Id = 2
2016-10-22 12:10:47.544 [DEBUG] [ZWaveMultiInstanceCommandClass:387 ]- NODE 25: Endpoints is dynamic = false
2016-10-22 12:10:47.544 [DEBUG] [ZWaveMultiInstanceCommandClass:388 ]- NODE 25: Basic = Routing Slave 0x04
2016-10-22 12:10:47.544 [DEBUG] [ZWaveMultiInstanceCommandClass:390 ]- NODE 25: Generic = Multi-Level Sensor 0x21
2016-10-22 12:10:47.544 [DEBUG] [ZWaveMultiInstanceCommandClass:392 ]- NODE 25: Specific = Routing Multilevel Sensor 0x01
2016-10-22 12:10:47.545 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MULTI_INSTANCE
2016-10-22 12:10:47.545 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class MULTI_INSTANCE.
2016-10-22 12:10:47.545 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class SENSOR_MULTILEVEL
2016-10-22 12:10:47.545 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class SENSOR_MULTILEVEL.
2016-10-22 12:10:47.545 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class CONFIGURATION
2016-10-22 12:10:47.545 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class CONFIGURATION.
2016-10-22 12:10:47.545 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class WAKE_UP
2016-10-22 12:10:47.546 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class WAKE_UP.
2016-10-22 12:10:47.546 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class ASSOCIATION
2016-10-22 12:10:47.546 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class ASSOCIATION.
2016-10-22 12:10:47.546 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class BATTERY
2016-10-22 12:10:47.546 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class BATTERY.
2016-10-22 12:10:47.546 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MANUFACTURER_SPECIFIC
2016-10-22 12:10:47.546 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class MANUFACTURER_SPECIFIC.
2016-10-22 12:10:47.546 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class NODE_NAMING
2016-10-22 12:10:47.547 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class NODE_NAMING.
2016-10-22 12:10:47.547 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class VERSION
2016-10-22 12:10:47.547 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class VERSION.
2016-10-22 12:10:47.547 [DEBUG] [ZWaveMultiInstanceCommandClass:386 ]- NODE 25: Endpoint Id = 3
2016-10-22 12:10:47.547 [DEBUG] [ZWaveMultiInstanceCommandClass:387 ]- NODE 25: Endpoints is dynamic = false
2016-10-22 12:10:47.547 [DEBUG] [ZWaveMultiInstanceCommandClass:388 ]- NODE 25: Basic = Routing Slave 0x04
2016-10-22 12:10:47.547 [DEBUG] [ZWaveMultiInstanceCommandClass:390 ]- NODE 25: Generic = Multi-Level Sensor 0x21
2016-10-22 12:10:47.548 [DEBUG] [ZWaveMultiInstanceCommandClass:392 ]- NODE 25: Specific = Routing Multilevel Sensor 0x01
2016-10-22 12:10:47.548 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MULTI_INSTANCE
2016-10-22 12:10:47.548 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class MULTI_INSTANCE.
2016-10-22 12:10:47.548 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class SENSOR_MULTILEVEL
2016-10-22 12:10:47.548 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class SENSOR_MULTILEVEL.
2016-10-22 12:10:47.548 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class CONFIGURATION
2016-10-22 12:10:47.548 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class CONFIGURATION.
2016-10-22 12:10:47.548 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class WAKE_UP
2016-10-22 12:10:47.549 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class WAKE_UP.
2016-10-22 12:10:47.549 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class ASSOCIATION
2016-10-22 12:10:47.549 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class ASSOCIATION.
2016-10-22 12:10:47.549 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class BATTERY
2016-10-22 12:10:47.549 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class BATTERY.
2016-10-22 12:10:47.549 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MANUFACTURER_SPECIFIC
2016-10-22 12:10:47.549 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class MANUFACTURER_SPECIFIC.
2016-10-22 12:10:47.550 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class NODE_NAMING
2016-10-22 12:10:47.550 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class NODE_NAMING.
2016-10-22 12:10:47.550 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class VERSION
2016-10-22 12:10:47.550 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class VERSION.
2016-10-22 12:10:47.551 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 25: Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-22 12:10:47.551 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - ENDPOINTS: Transaction complete (SendData:Request) success(true)
2016-10-22 12:10:47.551 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 3.
2016-10-22 12:10:47.551 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 2.
2016-10-22 12:10:47.551 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - ENDPOINTS: queue length(2), free to send(true)
2016-10-22 12:10:47.552 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 25: Node advancer - queued packet. Queue length is 2
2016-10-22 12:10:47.552 [DEBUG] [WaveController$ZWaveSendThread:1430]- NODE 25: Response processed for callback id 51 after 44ms/2082ms.
2016-10-22 12:10:47.552 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 25: Sending REQUEST Message = 01 0A 00 13 19 03 60 09 02 25 34 86 
2016-10-22 12:10:47.559 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 25: Sent Data successfully placed on stack.
2016-10-22 12:10:47.572 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 25: SendData Request. CallBack ID = 52, Status = Transmission complete and ACK received(0)
2016-10-22 12:10:47.584 [DEBUG] [ApplicationCommandMessageClass:41  ]- NODE 25: Application Command Request (ALIVE:ENDPOINTS)
2016-10-22 12:10:47.584 [DEBUG] [ApplicationCommandMessageClass:146 ]- NODE 25: Incoming command class MULTI_INSTANCE (0x60)
2016-10-22 12:10:47.584 [DEBUG] [ZWaveMultiInstanceCommandClass:138 ]- NODE 25: Received Multi-instance/Multi-channel Request
2016-10-22 12:10:47.584 [DEBUG] [ZWaveMultiInstanceCommandClass:307 ]- NODE 25: Process Multi-channel capability Report
2016-10-22 12:10:47.584 [DEBUG] [ZWaveMultiInstanceCommandClass:313 ]- NODE 25: Endpoints are the same device class = true
2016-10-22 12:10:47.584 [DEBUG] [ZWaveMultiInstanceCommandClass:386 ]- NODE 25: Endpoint Id = 1
2016-10-22 12:10:47.584 [DEBUG] [ZWaveMultiInstanceCommandClass:387 ]- NODE 25: Endpoints is dynamic = false
2016-10-22 12:10:47.585 [DEBUG] [ZWaveMultiInstanceCommandClass:388 ]- NODE 25: Basic = Routing Slave 0x04
2016-10-22 12:10:47.585 [DEBUG] [ZWaveMultiInstanceCommandClass:390 ]- NODE 25: Generic = Multi-Level Sensor 0x21
2016-10-22 12:10:47.585 [DEBUG] [ZWaveMultiInstanceCommandClass:392 ]- NODE 25: Specific = Routing Multilevel Sensor 0x01
2016-10-22 12:10:47.585 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MULTI_INSTANCE
2016-10-22 12:10:47.585 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class MULTI_INSTANCE.
2016-10-22 12:10:47.585 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class SENSOR_MULTILEVEL
2016-10-22 12:10:47.585 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class SENSOR_MULTILEVEL.
2016-10-22 12:10:47.586 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class CONFIGURATION
2016-10-22 12:10:47.586 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class CONFIGURATION.
2016-10-22 12:10:47.586 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class WAKE_UP
2016-10-22 12:10:47.586 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class WAKE_UP.
2016-10-22 12:10:47.586 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class ASSOCIATION
2016-10-22 12:10:47.587 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class ASSOCIATION.
2016-10-22 12:10:47.587 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class BATTERY
2016-10-22 12:10:47.587 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class BATTERY.
2016-10-22 12:10:47.588 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MANUFACTURER_SPECIFIC
2016-10-22 12:10:47.588 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class MANUFACTURER_SPECIFIC.
2016-10-22 12:10:47.588 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class NODE_NAMING
2016-10-22 12:10:47.588 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class NODE_NAMING.
2016-10-22 12:10:47.588 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class VERSION
2016-10-22 12:10:47.588 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class VERSION.
2016-10-22 12:10:47.588 [DEBUG] [ZWaveMultiInstanceCommandClass:386 ]- NODE 25: Endpoint Id = 2
2016-10-22 12:10:47.588 [DEBUG] [ZWaveMultiInstanceCommandClass:387 ]- NODE 25: Endpoints is dynamic = false
2016-10-22 12:10:47.588 [DEBUG] [ZWaveMultiInstanceCommandClass:388 ]- NODE 25: Basic = Routing Slave 0x04
2016-10-22 12:10:47.589 [DEBUG] [ZWaveMultiInstanceCommandClass:390 ]- NODE 25: Generic = Multi-Level Sensor 0x21
2016-10-22 12:10:47.589 [DEBUG] [ZWaveMultiInstanceCommandClass:392 ]- NODE 25: Specific = Routing Multilevel Sensor 0x01
2016-10-22 12:10:47.589 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MULTI_INSTANCE
2016-10-22 12:10:47.589 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class MULTI_INSTANCE.
2016-10-22 12:10:47.589 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class SENSOR_MULTILEVEL
2016-10-22 12:10:47.589 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class SENSOR_MULTILEVEL.
2016-10-22 12:10:47.589 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class CONFIGURATION
2016-10-22 12:10:47.589 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class CONFIGURATION.
2016-10-22 12:10:47.589 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class WAKE_UP
2016-10-22 12:10:47.590 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class WAKE_UP.
2016-10-22 12:10:47.590 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class ASSOCIATION
2016-10-22 12:10:47.590 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class ASSOCIATION.
2016-10-22 12:10:47.590 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class BATTERY
2016-10-22 12:10:47.590 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class BATTERY.
2016-10-22 12:10:47.590 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MANUFACTURER_SPECIFIC
2016-10-22 12:10:47.590 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class MANUFACTURER_SPECIFIC.
2016-10-22 12:10:47.590 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class NODE_NAMING
2016-10-22 12:10:47.591 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class NODE_NAMING.
2016-10-22 12:10:47.591 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class VERSION
2016-10-22 12:10:47.591 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class VERSION.
2016-10-22 12:10:47.591 [DEBUG] [ZWaveMultiInstanceCommandClass:386 ]- NODE 25: Endpoint Id = 3
2016-10-22 12:10:47.591 [DEBUG] [ZWaveMultiInstanceCommandClass:387 ]- NODE 25: Endpoints is dynamic = false
2016-10-22 12:10:47.591 [DEBUG] [ZWaveMultiInstanceCommandClass:388 ]- NODE 25: Basic = Routing Slave 0x04
2016-10-22 12:10:47.591 [DEBUG] [ZWaveMultiInstanceCommandClass:390 ]- NODE 25: Generic = Multi-Level Sensor 0x21
2016-10-22 12:10:47.591 [DEBUG] [ZWaveMultiInstanceCommandClass:392 ]- NODE 25: Specific = Routing Multilevel Sensor 0x01
2016-10-22 12:10:47.592 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MULTI_INSTANCE
2016-10-22 12:10:47.592 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class MULTI_INSTANCE.
2016-10-22 12:10:47.592 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class SENSOR_MULTILEVEL
2016-10-22 12:10:47.592 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class SENSOR_MULTILEVEL.
2016-10-22 12:10:47.592 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class CONFIGURATION
2016-10-22 12:10:47.592 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class CONFIGURATION.
2016-10-22 12:10:47.592 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class WAKE_UP
2016-10-22 12:10:47.592 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class WAKE_UP.
2016-10-22 12:10:47.593 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class ASSOCIATION
2016-10-22 12:10:47.593 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class ASSOCIATION.
2016-10-22 12:10:47.593 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class BATTERY
2016-10-22 12:10:47.593 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class BATTERY.
2016-10-22 12:10:47.593 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MANUFACTURER_SPECIFIC
2016-10-22 12:10:47.593 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class MANUFACTURER_SPECIFIC.
2016-10-22 12:10:47.593 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class NODE_NAMING
2016-10-22 12:10:47.593 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class NODE_NAMING.
2016-10-22 12:10:47.593 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class VERSION
2016-10-22 12:10:47.594 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class VERSION.
2016-10-22 12:10:47.594 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 25: Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-22 12:10:47.595 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - ENDPOINTS: Transaction complete (SendData:Request) success(true)
2016-10-22 12:10:47.595 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 2.
2016-10-22 12:10:47.595 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 1.
2016-10-22 12:10:47.595 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - ENDPOINTS: queue length(1), free to send(true)
2016-10-22 12:10:47.596 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 25: Node advancer - queued packet. Queue length is 1
2016-10-22 12:10:47.596 [DEBUG] [WaveController$ZWaveSendThread:1430]- NODE 25: Response processed for callback id 52 after 43ms/2082ms.
2016-10-22 12:10:47.597 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 25: Sending REQUEST Message = 01 0A 00 13 19 03 60 09 03 25 35 8

Avner · October 22, 2016, 7:33pm

And here are the messages after resatrting openhab and after pressing the button on hsm100 (part3)

2016-10-22 12:10:47.603 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 25: Sent Data successfully placed on stack.
2016-10-22 12:10:47.616 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 25: SendData Request. CallBack ID = 53, Status = Transmission complete and ACK received(0)
2016-10-22 12:10:47.627 [DEBUG] [ApplicationCommandMessageClass:41  ]- NODE 25: Application Command Request (ALIVE:ENDPOINTS)
2016-10-22 12:10:47.628 [DEBUG] [ApplicationCommandMessageClass:146 ]- NODE 25: Incoming command class MULTI_INSTANCE (0x60)
2016-10-22 12:10:47.628 [DEBUG] [ZWaveMultiInstanceCommandClass:138 ]- NODE 25: Received Multi-instance/Multi-channel Request
2016-10-22 12:10:47.628 [DEBUG] [ZWaveMultiInstanceCommandClass:307 ]- NODE 25: Process Multi-channel capability Report
2016-10-22 12:10:47.628 [DEBUG] [ZWaveMultiInstanceCommandClass:313 ]- NODE 25: Endpoints are the same device class = true
2016-10-22 12:10:47.628 [DEBUG] [ZWaveMultiInstanceCommandClass:386 ]- NODE 25: Endpoint Id = 1
2016-10-22 12:10:47.628 [DEBUG] [ZWaveMultiInstanceCommandClass:387 ]- NODE 25: Endpoints is dynamic = false
2016-10-22 12:10:47.628 [DEBUG] [ZWaveMultiInstanceCommandClass:388 ]- NODE 25: Basic = Routing Slave 0x04
2016-10-22 12:10:47.628 [DEBUG] [ZWaveMultiInstanceCommandClass:390 ]- NODE 25: Generic = Multi-Level Sensor 0x21
2016-10-22 12:10:47.628 [DEBUG] [ZWaveMultiInstanceCommandClass:392 ]- NODE 25: Specific = Routing Multilevel Sensor 0x01
2016-10-22 12:10:47.628 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MULTI_INSTANCE
2016-10-22 12:10:47.629 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class MULTI_INSTANCE.
2016-10-22 12:10:47.629 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class SENSOR_MULTILEVEL
2016-10-22 12:10:47.629 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class SENSOR_MULTILEVEL.
2016-10-22 12:10:47.629 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class CONFIGURATION
2016-10-22 12:10:47.629 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class CONFIGURATION.
2016-10-22 12:10:47.629 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class WAKE_UP
2016-10-22 12:10:47.630 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class WAKE_UP.
2016-10-22 12:10:47.630 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class ASSOCIATION
2016-10-22 12:10:47.630 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class ASSOCIATION.
2016-10-22 12:10:47.630 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class BATTERY
2016-10-22 12:10:47.630 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class BATTERY.
2016-10-22 12:10:47.630 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MANUFACTURER_SPECIFIC
2016-10-22 12:10:47.630 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class MANUFACTURER_SPECIFIC.
2016-10-22 12:10:47.630 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class NODE_NAMING
2016-10-22 12:10:47.630 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class NODE_NAMING.
2016-10-22 12:10:47.630 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class VERSION
2016-10-22 12:10:47.630 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 1: Adding command class VERSION.
2016-10-22 12:10:47.631 [DEBUG] [ZWaveMultiInstanceCommandClass:386 ]- NODE 25: Endpoint Id = 2
2016-10-22 12:10:47.631 [DEBUG] [ZWaveMultiInstanceCommandClass:387 ]- NODE 25: Endpoints is dynamic = false
2016-10-22 12:10:47.631 [DEBUG] [ZWaveMultiInstanceCommandClass:388 ]- NODE 25: Basic = Routing Slave 0x04
2016-10-22 12:10:47.631 [DEBUG] [ZWaveMultiInstanceCommandClass:390 ]- NODE 25: Generic = Multi-Level Sensor 0x21
2016-10-22 12:10:47.631 [DEBUG] [ZWaveMultiInstanceCommandClass:392 ]- NODE 25: Specific = Routing Multilevel Sensor 0x01
2016-10-22 12:10:47.631 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MULTI_INSTANCE
2016-10-22 12:10:47.631 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class MULTI_INSTANCE.
2016-10-22 12:10:47.631 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class SENSOR_MULTILEVEL
2016-10-22 12:10:47.631 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class SENSOR_MULTILEVEL.
2016-10-22 12:10:47.631 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class CONFIGURATION
2016-10-22 12:10:47.632 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class CONFIGURATION.
2016-10-22 12:10:47.632 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class WAKE_UP
2016-10-22 12:10:47.632 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class WAKE_UP.
2016-10-22 12:10:47.632 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class ASSOCIATION
2016-10-22 12:10:47.632 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class ASSOCIATION.
2016-10-22 12:10:47.632 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class BATTERY
2016-10-22 12:10:47.632 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class BATTERY.
2016-10-22 12:10:47.632 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MANUFACTURER_SPECIFIC
2016-10-22 12:10:47.633 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class MANUFACTURER_SPECIFIC.
2016-10-22 12:10:47.633 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class NODE_NAMING
2016-10-22 12:10:47.633 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class NODE_NAMING.
2016-10-22 12:10:47.633 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class VERSION
2016-10-22 12:10:47.633 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 2: Adding command class VERSION.
2016-10-22 12:10:47.633 [DEBUG] [ZWaveMultiInstanceCommandClass:386 ]- NODE 25: Endpoint Id = 3
2016-10-22 12:10:47.633 [DEBUG] [ZWaveMultiInstanceCommandClass:387 ]- NODE 25: Endpoints is dynamic = false
2016-10-22 12:10:47.633 [DEBUG] [ZWaveMultiInstanceCommandClass:388 ]- NODE 25: Basic = Routing Slave 0x04
2016-10-22 12:10:47.633 [DEBUG] [ZWaveMultiInstanceCommandClass:390 ]- NODE 25: Generic = Multi-Level Sensor 0x21
2016-10-22 12:10:47.633 [DEBUG] [ZWaveMultiInstanceCommandClass:392 ]- NODE 25: Specific = Routing Multilevel Sensor 0x01
2016-10-22 12:10:47.634 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MULTI_INSTANCE
2016-10-22 12:10:47.634 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class MULTI_INSTANCE.
2016-10-22 12:10:47.634 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class SENSOR_MULTILEVEL
2016-10-22 12:10:47.634 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class SENSOR_MULTILEVEL.
2016-10-22 12:10:47.634 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class CONFIGURATION
2016-10-22 12:10:47.634 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class CONFIGURATION.
2016-10-22 12:10:47.634 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class WAKE_UP
2016-10-22 12:10:47.634 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class WAKE_UP.
2016-10-22 12:10:47.634 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class ASSOCIATION
2016-10-22 12:10:47.635 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class ASSOCIATION.
2016-10-22 12:10:47.635 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class BATTERY
2016-10-22 12:10:47.635 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class BATTERY.
2016-10-22 12:10:47.635 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class MANUFACTURER_SPECIFIC
2016-10-22 12:10:47.635 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class MANUFACTURER_SPECIFIC.
2016-10-22 12:10:47.635 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class NODE_NAMING
2016-10-22 12:10:47.635 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class NODE_NAMING.
2016-10-22 12:10:47.635 [DEBUG] [.o.b.z.i.p.c.ZWaveCommandClass:241 ]- NODE 25: Creating new instance of command class VERSION
2016-10-22 12:10:47.635 [DEBUG] [ZWaveMultiInstanceCommandClass:426 ]- NODE 25: Endpoint 3: Adding command class VERSION.
2016-10-22 12:10:47.636 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 25: Notifying event listeners: ZWaveTransactionCompletedEvent
2016-10-22 12:10:47.636 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1116]- NODE 25: Node advancer - ENDPOINTS: Transaction complete (SendData:Request) success(true)
2016-10-22 12:10:47.636 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 25: Node advancer - checking initialisation queue. Queue size 1.
2016-10-22 12:10:47.636 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 25: Node advancer - message removed from queue. Queue size 0.
2016-10-22 12:10:47.636 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 25: Node advancer - ENDPOINTS: queue length(0), free to send(true)
2016-10-22 12:10:47.637 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - ENDPOINTS try 2: stageAdvanced(false)
2016-10-22 12:10:47.637 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:602 ]- NODE 25: Node advancer: ENDPOINTS - MultiInstance is supported
2016-10-22 12:10:47.637 [DEBUG] [ZWaveMultiInstanceCommandClass:614 ]- NODE 25: Initialising endpoints - version 2
2016-10-22 12:10:47.637 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:605 ]- NODE 25: Node advancer: ENDPOINTS - queued 0 frames
2016-10-22 12:10:47.637 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to UPDATE_DATABASE
2016-10-22 12:10:47.637 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - UPDATE_DATABASE try 0: stageAdvanced(true)
2016-10-22 12:10:47.637 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:619 ]- NODE 25: Node advancer: UPDATE_DATABASE
2016-10-22 12:10:47.654 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 25: Node advancer - advancing to STATIC_VALUES
2016-10-22 12:10:47.655 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 25: Node advancer: loop - STATIC_VALUES try 0: stageAdvanced(true)
2016-10-22 12:10:47.655 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 25: Node advancer: STATIC_VALUES - checking SENSOR_MULTILEVEL
2016-10-22 12:10:47.655 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:673 ]- NODE 25: Node advancer: STATIC_VALUES - found    SENSOR_MULTILEVEL
2016-10-22 12:10:47.655 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:677 ]- NODE 25: Found 1 instances of SENSOR_MULTILEVEL
2016-10-22 12:10:47.655 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 25: Node advancer: STATIC_VALUES - checking CONFIGURATION
2016-10-22 12:10:47.655 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 25: Node advancer: STATIC_VALUES - checking ASSOCIATION
2016-10-22 12:10:47.655 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:673 ]- NODE 25: Node advancer: STATIC_VALUES - found    ASSOCIATION
2016-10-22 12:10:47.655 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:677 ]- NODE 25: Found 1 instances of ASSOCIATION
2016-10-22 12:10:47.655 [DEBUG] [c.ZWaveAssociationCommandClass:312 ]- NODE 25: Creating new message for application command ASSOCIATIONCMD_GROUPINGSGET
2016-10-22 12:10:47.656 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.656 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 25: Node advancer: STATIC_VALUES - checking NODE_NAMING
2016-10-22 12:10:47.656 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:673 ]- NODE 25: Node advancer: STATIC_VALUES - found    NODE_NAMING
2016-10-22 12:10:47.656 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:677 ]- NODE 25: Found 1 instances of NODE_NAMING
2016-10-22 12:10:47.656 [DEBUG] [.c.ZWaveNodeNamingCommandClass:281 ]- NODE 25: Creating new message for application command NAME_GET
2016-10-22 12:10:47.656 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.656 [DEBUG] [.c.ZWaveNodeNamingCommandClass:296 ]- NODE 25: Creating new message for application command LOCATION_GET
2016-10-22 12:10:47.656 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.657 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 25: Node advancer: STATIC_VALUES - checking VERSION
2016-10-22 12:10:47.657 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 25: Node advancer: STATIC_VALUES - checking MANUFACTURER_SPECIFIC
2016-10-22 12:10:47.657 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 25: Node advancer: STATIC_VALUES - checking NO_OPERATION
2016-10-22 12:10:47.657 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 25: Node advancer: STATIC_VALUES - checking BASIC
2016-10-22 12:10:47.657 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 25: Node advancer: STATIC_VALUES - checking WAKE_UP
2016-10-22 12:10:47.657 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:673 ]- NODE 25: Node advancer: STATIC_VALUES - found    WAKE_UP
2016-10-22 12:10:47.657 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:677 ]- NODE 25: Found 1 instances of WAKE_UP
2016-10-22 12:10:47.657 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:279 ]- NODE 25: Creating new message for application command WAKE_UP_INTERVAL_GET
2016-10-22 12:10:47.657 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.657 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:300 ]- NODE 25: Creating new message for application command WAKE_UP_INTERVAL_CAPABILITIES_GET
2016-10-22 12:10:47.658 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.658 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 25: Node advancer: STATIC_VALUES - checking BATTERY
2016-10-22 12:10:47.658 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 25: Node advancer: STATIC_VALUES - checking MULTI_INSTANCE
2016-10-22 12:10:47.658 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 25: Node advancer: STATIC_VALUES - checking SENSOR_MULTILEVEL for endpoint 1
2016-10-22 12:10:47.658 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 25: Node advancer: STATIC_VALUES - found    SENSOR_MULTILEVEL
2016-10-22 12:10:47.658 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 25: Node advancer: STATIC_VALUES - checking CONFIGURATION for endpoint 1
2016-10-22 12:10:47.658 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 25: Node advancer: STATIC_VALUES - checking ASSOCIATION for endpoint 1
2016-10-22 12:10:47.658 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 25: Node advancer: STATIC_VALUES - found    ASSOCIATION
2016-10-22 12:10:47.658 [DEBUG] [c.ZWaveAssociationCommandClass:312 ]- NODE 25: Creating new message for application command ASSOCIATIONCMD_GROUPINGSGET
2016-10-22 12:10:47.658 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.658 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 25: Encapsulating message, instance / endpoint 1
2016-10-22 12:10:47.659 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 25: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2016-10-22 12:10:47.659 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 25: Node advancer: STATIC_VALUES - checking NODE_NAMING for endpoint 1
2016-10-22 12:10:47.659 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 25: Node advancer: STATIC_VALUES - found    NODE_NAMING
2016-10-22 12:10:47.659 [DEBUG] [.c.ZWaveNodeNamingCommandClass:281 ]- NODE 25: Creating new message for application command NAME_GET
2016-10-22 12:10:47.659 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.659 [DEBUG] [.c.ZWaveNodeNamingCommandClass:296 ]- NODE 25: Creating new message for application command LOCATION_GET
2016-10-22 12:10:47.659 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.659 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 25: Encapsulating message, instance / endpoint 1
2016-10-22 12:10:47.659 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 25: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2016-10-22 12:10:47.659 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 25: Encapsulating message, instance / endpoint 1
2016-10-22 12:10:47.659 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 25: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2016-10-22 12:10:47.660 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 25: Node advancer: STATIC_VALUES - checking VERSION for endpoint 1
2016-10-22 12:10:47.660 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 25: Node advancer: STATIC_VALUES - checking MANUFACTURER_SPECIFIC for endpoint 1
2016-10-22 12:10:47.660 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 25: Node advancer: STATIC_VALUES - checking BASIC for endpoint 1
2016-10-22 12:10:47.660 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 25: Node advancer: STATIC_VALUES - checking WAKE_UP for endpoint 1
2016-10-22 12:10:47.660 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 25: Node advancer: STATIC_VALUES - found    WAKE_UP
2016-10-22 12:10:47.660 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:279 ]- NODE 25: Creating new message for application command WAKE_UP_INTERVAL_GET
2016-10-22 12:10:47.660 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.660 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:300 ]- NODE 25: Creating new message for application command WAKE_UP_INTERVAL_CAPABILITIES_GET
2016-10-22 12:10:47.660 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.660 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 25: Encapsulating message, instance / endpoint 1
2016-10-22 12:10:47.660 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 25: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2016-10-22 12:10:47.661 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 25: Encapsulating message, instance / endpoint 1
2016-10-22 12:10:47.661 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 25: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2016-10-22 12:10:47.661 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 25: Node advancer: STATIC_VALUES - checking BATTERY for endpoint 1
2016-10-22 12:10:47.661 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 25: Node advancer: STATIC_VALUES - checking MULTI_INSTANCE for endpoint 1
2016-10-22 12:10:47.661 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 25: Node advancer: STATIC_VALUES - checking SENSOR_MULTILEVEL for endpoint 2
2016-10-22 12:10:47.661 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 25: Node advancer: STATIC_VALUES - found    SENSOR_MULTILEVEL
2016-10-22 12:10:47.661 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 25: Node advancer: STATIC_VALUES - checking CONFIGURATION for endpoint 2
2016-10-22 12:10:47.661 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 25: Node advancer: STATIC_VALUES - checking ASSOCIATION for endpoint 2
2016-10-22 12:10:47.661 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 25: Node advancer: STATIC_VALUES - found    ASSOCIATION
2016-10-22 12:10:47.661 [DEBUG] [c.ZWaveAssociationCommandClass:312 ]- NODE 25: Creating new message for application command ASSOCIATIONCMD_GROUPINGSGET
2016-10-22 12:10:47.661 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 25: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-22 12:10:47.661 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 25: Encapsulating message, instance / endpoint 2
2016-10-22 12:10:47.662 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 25: Creating new message for command MULTI_CHANNEL_ENCAP endpoin

chris · October 22, 2016, 10:04pm

It looks like initialisation is/was proceding fine. I would try waking it again - maybe the binding things it’s gone to sleep… There’s no indication that it thinks this, but if the logs stop here then that would be my guess. Otherwise it looks ok so far.

Avner · October 23, 2016, 7:13am

I woke it up again (by physically pressing the single button on the device) but the xml file is still missing

I see that the device was in wakeup mode during intialization

2016-10-22 12:10:46.035 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1140]- NODE 25: Wakeup during initialisation.

I restarted openhab in debug mode (using sudo ./start_debug.sh)
and I see that wakeup is not supported, and that the node has not completed initialization. Are these messagse expected?

grep -i "node 25:" logs/openhab.log
...
17:01:16.861 [DEBUG] [.z.i.config.ZWaveConfiguration:786  ] - NODE 25: wakeupCommandClass not supported
17:01:19.512 [DEBUG] [.z.internal.ZWaveActiveBinding:194  ] - NODE 25: Polling list: item Motion_gAllFloors is not completed initialisation
17:01:19.513 [DEBUG] [.z.internal.ZWaveActiveBinding:194  ] - NODE 25: Polling list: item Temperature_gAllFloors is not completed initialisation

In any case the node25.xml file is still missing.

17:07:50.068 [DEBUG] [b.z.i.protocol.ZWaveController:512  ] - NODE 25: Init node thread start
17:07:50.286 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:138  ] - NODE 25: Serializing from file etc/zwave/node25.xml
17:07:50.289 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:141  ] - NODE 25: Error serializing from file: file does not exist.

chris · October 23, 2016, 8:30am

To get the xml file the device needs to be woken up so that the binding can download information about the device. This was working ok in the logs you sent earlier and it should just need to be woken up maybe a few more times.

Wake up is supported but since you have now restarted the binding, it doesn’t know this until it has communicated with the device.

Avner · October 23, 2016, 8:39am

I excluded / included the device again. No luck:
When I physically press the button on the device (i.e. wake up the device), habmin populates “EZMotion Express Wireless 3 in 1 sensor” next to the node.

I see some error messages. It seems that the initialization of the node doesn’t complete?

grep -i "node 28" logs/zwave.log
...
2016-10-23 01:02:29.276 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 28: Node advancer - WAIT: queue length(0), free to send(true)
2016-10-23 01:02:29.276 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 28: Node advancer: loop - WAIT try 2: stageAdvanced(false)
2016-10-23 01:02:29.276 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:390 ]- NODE 28: Node advancer: WAIT - Listening=false, FrequentlyListening=false
2016-10-23 01:02:29.276 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:402 ]- NODE 28: Node advancer: WAIT - Node is awake
2016-10-23 01:02:29.276 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:972 ]- NODE 28: Node advancer - advancing to PING
2016-10-23 01:02:29.277 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 28: Node advancer: loop - PING try 0: stageAdvanced(true)
2016-10-23 01:02:29.277 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:427 ]- NODE 28: Node advancer: PING - send NoOperation
2016-10-23 01:02:29.277 [DEBUG] [c.ZWaveNoOperationCommandClass:72  ]- NODE 28: Creating new message for command No Operation
2016-10-23 01:02:29.277 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 01:02:29.278 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 28: Node advancer - queued packet. Queue length is 1
2016-10-23 01:02:30.271 [DEBUG] [ApplicationCommandMessageClass:41  ]- NODE 28: Application Command Request (ALIVE:PING)
2016-10-23 01:02:30.271 [DEBUG] [ApplicationCommandMessageClass:146 ]- NODE 28: Incoming command class WAKE_UP (0x84)
2016-10-23 01:02:30.271 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:140 ]- NODE 28: Received Wake Up Request
2016-10-23 01:02:30.271 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:199 ]- NODE 28: Received WAKE_UP_NOTIFICATION
2016-10-23 01:02:30.271 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:449 ]- NODE 28: Is awake with 0 messages in the wake-up queue.
2016-10-23 01:02:30.271 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 28: Notifying event listeners: ZWaveWakeUpEvent
2016-10-23 01:02:30.272 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1140]- NODE 28: Wakeup during initialisation.
2016-10-23 01:02:30.272 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 28: Node advancer - PING: queue length(1), free to send(false)
2016-10-23 01:02:30.272 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 28: Node advancer - queued packet. Queue length is 1
2016-10-23 01:02:31.272 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:544 ]- NODE 28: No more messages, go back to sleep
...
2016-10-23 01:03:21.211 [**ERROR**] [WaveController$ZWaveSendThread:1413]- NODE 28: Timeout while sending message. Requeueing - 0 attempts left!
2016-10-23 01:03:21.212 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:472 ]- NODE 28: Is sleeping
2016-10-23 01:03:21.212 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:260 ]- NODE 28: Putting message SendData in wakeup queue.
2016-10-23 01:03:21.212 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:260 ]- NODE 28: Putting message SendData in wakeup queue.
2016-10-23 01:03:44.010 [**ERROR**] [.z.i.config.ZWaveConfiguration:1124]- NODE 28: Error in doSet - no database found
...
2016-10-23 01:06:21.711 [**ERROR**] [b.z.i.p.s.SendDataMessageClass:43  ]- NODE 28: Sent Data was not placed on stack due to error 0.
...
2016-10-23 01:10:05.639 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:208 ]- NODE 28: Node advancer - checking initialisation queue. Queue size 1.
2016-10-23 01:10:05.639 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:214 ]- NODE 28: Node advancer - message removed from queue. Queue size 0.
2016-10-23 01:10:05.639 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 28: Node advancer - MANUFACTURER: queue length(0), free to send(true)
2016-10-23 01:10:05.639 [**ERROR**] [z.i.p.i.ZWaveNodeStageAdvancer:324 ]- NODE 28: Node advancer: Retries exceeded at MANUFACTURER
2016-10-23 01:10:05.639 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:336 ]- NODE 28: Retry timout: Can't advance

chris · October 23, 2016, 9:09am

Timeouts will happen from time to time. If it is systematic, then it’s likely that there is another issue like the distance is too far or something. The other error is because the device hasn’t initialised yet and the binding doesn’t know the device type when you try and do something.[quote=“Avner, post:14, topic:15589”]
habmin populates “EZMotion Express Wireless 3 in 1 sensor” next to the node.
[/quote]

Then this is likely what the device really is. It’s common for devices to be rebranded. If the device is completely diferent, then it means someone entered wrong data into the database.

Avner · October 23, 2016, 5:33pm

Is the database error expected?

2016-10-23 01:03:44.010 [ERROR] [.z.i.config.ZWaveConfiguration:1124]- NODE 28: Error in doSet - no database found

The timeout seems systematic (I have tried several times) and the distance between the device and the controller is short (about 1 meter)

chris · October 23, 2016, 5:41pm

Yes - as I said “The other error is because the device hasn’t initialised yet and the binding doesn’t know the device type when you try and do something.”

Please provide the log showing this - it’s not clear.

Avner · October 23, 2016, 5:46pm

While waking up the device I also get a warning, followed by the timeout error
Here is the log related to the motion sensor
Any ideas what to do next?

2016-10-23 10:39:10.983 [DEBUG] [.ApplicationUpdateMessageClass:49  ]- NODE 28: Application update request. Node information received.
2016-10-23 10:39:10.984 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 28: Notifying event listeners: ZWaveNodeInfoEvent
2016-10-23 10:39:10.984 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 28: 22 NIF event during initialisation stage PING
2016-10-23 10:39:10.984 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 28: 13 NIF event during initialisation stage PING
2016-10-23 10:39:10.984 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 28: 28 NIF event during initialisation stage STATIC_VALUES
2016-10-23 10:39:10.984 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1174]- NODE 28: NIF event during initialisation stage STATIC_VALUES
2016-10-23 10:39:10.984 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 28: Node advancer - STATIC_VALUES: queue length(17), free to send(false)
2016-10-23 10:39:10.984 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:255 ]- NODE 28: Message already on the wake-up queue. Removing original.
2016-10-23 10:39:10.985 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:260 ]- NODE 28: Putting message SendData in wakeup queue.
2016-10-23 10:39:10.985 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 28: Node advancer - queued packet. Queue length is 17
2016-10-23 10:39:10.985 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 28: 9 NIF event during initialisation stage PING
2016-10-23 10:39:10.985 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 28: 18 NIF event during initialisation stage PING
2016-10-23 10:39:10.985 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 28: 16 NIF event during initialisation stage PING
2016-10-23 10:39:10.985 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1164]- NODE 28: 17 NIF event during initialisation stage DETAILS
2016-10-23 10:39:10.985 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:449 ]- NODE 28: Is awake with 2 messages in the wake-up queue.
2016-10-23 10:39:10.985 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 28: Notifying event listeners: ZWaveWakeUpEvent
2016-10-23 10:39:10.985 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1140]- NODE 28: Wakeup during initialisation.
2016-10-23 10:39:10.986 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 28: Node advancer - STATIC_VALUES: queue length(17), free to send(false)
2016-10-23 10:39:10.986 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:342 ]- NODE 28: Node advancer: loop - STATIC_VALUES try 4: stageAdvanced(false)
2016-10-23 10:39:10.986 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 28: Node advancer: STATIC_VALUES - checking BASIC
2016-10-23 10:39:10.986 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 28: Node advancer: STATIC_VALUES - checking ASSOCIATION
2016-10-23 10:39:10.986 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:673 ]- NODE 28: Node advancer: STATIC_VALUES - found    ASSOCIATION
2016-10-23 10:39:10.986 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:677 ]- NODE 28: Found 1 instances of ASSOCIATION
2016-10-23 10:39:10.986 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 28: Node advancer: STATIC_VALUES - checking BATTERY
2016-10-23 10:39:10.986 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 28: Node advancer: STATIC_VALUES - checking NODE_NAMING
2016-10-23 10:39:10.986 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:673 ]- NODE 28: Node advancer: STATIC_VALUES - found    NODE_NAMING
2016-10-23 10:39:10.987 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:677 ]- NODE 28: Found 1 instances of NODE_NAMING
2016-10-23 10:39:10.987 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 28: Node advancer: STATIC_VALUES - checking MULTI_INSTANCE
2016-10-23 10:39:10.987 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking BASIC for endpoint 1
2016-10-23 10:39:10.987 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking ASSOCIATION for endpoint 1
2016-10-23 10:39:10.987 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 28: Node advancer: STATIC_VALUES - found    ASSOCIATION
2016-10-23 10:39:10.987 [DEBUG] [c.ZWaveAssociationCommandClass:312 ]- NODE 28: Creating new message for application command ASSOCIATIONCMD_GROUPINGSGET
2016-10-23 10:39:10.987 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:10.987 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 28: Encapsulating message, instance / endpoint 1
2016-10-23 10:39:10.987 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 28: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2016-10-23 10:39:10.988 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking BATTERY for endpoint 1
2016-10-23 10:39:10.988 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking NODE_NAMING for endpoint 1
2016-10-23 10:39:10.988 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 28: Node advancer: STATIC_VALUES - found    NODE_NAMING
2016-10-23 10:39:10.988 [DEBUG] [.c.ZWaveNodeNamingCommandClass:281 ]- NODE 28: Creating new message for application command NAME_GET
2016-10-23 10:39:10.988 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:10.988 [DEBUG] [.c.ZWaveNodeNamingCommandClass:296 ]- NODE 28: Creating new message for application command LOCATION_GET
2016-10-23 10:39:10.988 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:10.988 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 28: Encapsulating message, instance / endpoint 1
2016-10-23 10:39:10.989 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 28: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2016-10-23 10:39:10.989 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 28: Encapsulating message, instance / endpoint 1
2016-10-23 10:39:10.989 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 28: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2016-10-23 10:39:10.989 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking MULTI_INSTANCE for endpoint 1
2016-10-23 10:39:10.989 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking CONFIGURATION for endpoint 1
2016-10-23 10:39:10.989 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking SENSOR_MULTILEVEL for endpoint 1
2016-10-23 10:39:10.989 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 28: Node advancer: STATIC_VALUES - found    SENSOR_MULTILEVEL
2016-10-23 10:39:10.989 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking MANUFACTURER_SPECIFIC for endpoint 1
2016-10-23 10:39:10.990 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking VERSION for endpoint 1
2016-10-23 10:39:10.990 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking WAKE_UP for endpoint 1
2016-10-23 10:39:10.990 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 28: Node advancer: STATIC_VALUES - found    WAKE_UP
2016-10-23 10:39:10.990 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:279 ]- NODE 28: Creating new message for application command WAKE_UP_INTERVAL_GET
2016-10-23 10:39:10.990 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:10.990 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:300 ]- NODE 28: Creating new message for application command WAKE_UP_INTERVAL_CAPABILITIES_GET
2016-10-23 10:39:10.990 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:10.990 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 28: Encapsulating message, instance / endpoint 1
2016-10-23 10:39:10.990 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 28: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2016-10-23 10:39:10.991 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 28: Encapsulating message, instance / endpoint 1
2016-10-23 10:39:10.991 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 28: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2016-10-23 10:39:10.991 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking BASIC for endpoint 2
2016-10-23 10:39:10.991 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking ASSOCIATION for endpoint 2
2016-10-23 10:39:10.991 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 28: Node advancer: STATIC_VALUES - found    ASSOCIATION
2016-10-23 10:39:10.992 [DEBUG] [c.ZWaveAssociationCommandClass:312 ]- NODE 28: Creating new message for application command ASSOCIATIONCMD_GROUPINGSGET
2016-10-23 10:39:10.992 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:10.992 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 28: Encapsulating message, instance / endpoint 2
2016-10-23 10:39:10.992 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 28: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2
2016-10-23 10:39:10.992 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking BATTERY for endpoint 2
2016-10-23 10:39:10.993 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking NODE_NAMING for endpoint 2
2016-10-23 10:39:10.993 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 28: Node advancer: STATIC_VALUES - found    NODE_NAMING
2016-10-23 10:39:10.993 [DEBUG] [.c.ZWaveNodeNamingCommandClass:281 ]- NODE 28: Creating new message for application command NAME_GET
2016-10-23 10:39:10.993 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:10.993 [DEBUG] [.c.ZWaveNodeNamingCommandClass:296 ]- NODE 28: Creating new message for application command LOCATION_GET
2016-10-23 10:39:10.993 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:10.993 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 28: Encapsulating message, instance / endpoint 2
2016-10-23 10:39:10.993 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 28: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2
2016-10-23 10:39:10.994 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 28: Encapsulating message, instance / endpoint 2
2016-10-23 10:39:10.994 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 28: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2
2016-10-23 10:39:10.994 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking MULTI_INSTANCE for endpoint 2
2016-10-23 10:39:10.994 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking CONFIGURATION for endpoint 2
2016-10-23 10:39:10.994 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking SENSOR_MULTILEVEL for endpoint 2
2016-10-23 10:39:10.994 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 28: Node advancer: STATIC_VALUES - found    SENSOR_MULTILEVEL
2016-10-23 10:39:10.994 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking MANUFACTURER_SPECIFIC for endpoint 2
2016-10-23 10:39:10.994 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking VERSION for endpoint 2
2016-10-23 10:39:10.994 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking WAKE_UP for endpoint 2
2016-10-23 10:39:10.994 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 28: Node advancer: STATIC_VALUES - found    WAKE_UP
2016-10-23 10:39:10.995 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:279 ]- NODE 28: Creating new message for application command WAKE_UP_INTERVAL_GET
2016-10-23 10:39:10.995 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:10.995 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:300 ]- NODE 28: Creating new message for application command WAKE_UP_INTERVAL_CAPABILITIES_GET
2016-10-23 10:39:10.995 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:10.995 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 28: Encapsulating message, instance / endpoint 2
2016-10-23 10:39:10.995 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 28: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2
2016-10-23 10:39:10.995 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 28: Encapsulating message, instance / endpoint 2
2016-10-23 10:39:10.995 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 28: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 2
2016-10-23 10:39:10.996 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking BASIC for endpoint 3
2016-10-23 10:39:10.996 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking ASSOCIATION for endpoint 3
2016-10-23 10:39:10.996 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 28: Node advancer: STATIC_VALUES - found    ASSOCIATION
2016-10-23 10:39:10.996 [DEBUG] [c.ZWaveAssociationCommandClass:312 ]- NODE 28: Creating new message for application command ASSOCIATIONCMD_GROUPINGSGET
2016-10-23 10:39:10.996 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:10.996 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 28: Encapsulating message, instance / endpoint 3
2016-10-23 10:39:10.996 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 28: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 3
2016-10-23 10:39:10.996 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking BATTERY for endpoint 3
2016-10-23 10:39:10.997 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking NODE_NAMING for endpoint 3
2016-10-23 10:39:10.997 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 28: Node advancer: STATIC_VALUES - found    NODE_NAMING
2016-10-23 10:39:10.997 [DEBUG] [.c.ZWaveNodeNamingCommandClass:281 ]- NODE 28: Creating new message for application command NAME_GET
2016-10-23 10:39:10.997 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:10.997 [DEBUG] [.c.ZWaveNodeNamingCommandClass:296 ]- NODE 28: Creating new message for application command LOCATION_GET
2016-10-23 10:39:10.997 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:10.997 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 28: Encapsulating message, instance / endpoint 3
2016-10-23 10:39:10.997 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 28: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 3
2016-10-23 10:39:10.998 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 28: Encapsulating message, instance / endpoint 3
2016-10-23 10:39:10.998 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 28: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 3
2016-10-23 10:39:10.998 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking MULTI_INSTANCE for endpoint 3
2016-10-23 10:39:10.998 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking CONFIGURATION for endpoint 3
2016-10-23 10:39:10.998 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking SENSOR_MULTILEVEL for endpoint 3
2016-10-23 10:39:10.998 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 28: Node advancer: STATIC_VALUES - found    SENSOR_MULTILEVEL
2016-10-23 10:39:10.998 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking MANUFACTURER_SPECIFIC for endpoint 3
2016-10-23 10:39:10.998 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking VERSION for endpoint 3
2016-10-23 10:39:10.998 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:690 ]- NODE 28: Node advancer: STATIC_VALUES - checking WAKE_UP for endpoint 3
2016-10-23 10:39:10.998 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:694 ]- NODE 28: Node advancer: STATIC_VALUES - found    WAKE_UP
2016-10-23 10:39:10.999 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:279 ]- NODE 28: Creating new message for application command WAKE_UP_INTERVAL_GET
2016-10-23 10:39:10.999 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:10.999 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:300 ]- NODE 28: Creating new message for application command WAKE_UP_INTERVAL_CAPABILITIES_GET
2016-10-23 10:39:10.999 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:10.999 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 28: Encapsulating message, instance / endpoint 3
2016-10-23 10:39:10.999 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 28: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 3
2016-10-23 10:39:10.999 [DEBUG] [.z.internal.protocol.ZWaveNode:716 ]- NODE 28: Encapsulating message, instance / endpoint 3
2016-10-23 10:39:10.999 [DEBUG] [ZWaveMultiInstanceCommandClass:588 ]- NODE 28: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 3
2016-10-23 10:39:11.000 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 28: Node advancer: STATIC_VALUES - checking CONFIGURATION
2016-10-23 10:39:11.000 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 28: Node advancer: STATIC_VALUES - checking NO_OPERATION
2016-10-23 10:39:11.000 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 28: Node advancer: STATIC_VALUES - checking SENSOR_MULTILEVEL
2016-10-23 10:39:11.000 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:673 ]- NODE 28: Node advancer: STATIC_VALUES - found    SENSOR_MULTILEVEL
2016-10-23 10:39:11.000 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:677 ]- NODE 28: Found 1 instances of SENSOR_MULTILEVEL
2016-10-23 10:39:11.000 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 28: Node advancer: STATIC_VALUES - checking MANUFACTURER_SPECIFIC
2016-10-23 10:39:11.000 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 28: Node advancer: STATIC_VALUES - checking VERSION
2016-10-23 10:39:11.000 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:670 ]- NODE 28: Node advancer: STATIC_VALUES - checking WAKE_UP
2016-10-23 10:39:11.000 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:673 ]- NODE 28: Node advancer: STATIC_VALUES - found    WAKE_UP
2016-10-23 10:39:11.000 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:677 ]- NODE 28: Found 1 instances of WAKE_UP
2016-10-23 10:39:11.000 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:279 ]- NODE 28: Creating new message for application command WAKE_UP_INTERVAL_GET
2016-10-23 10:39:11.001 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:11.001 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:300 ]- NODE 28: Creating new message for application command WAKE_UP_INTERVAL_CAPABILITIES_GET
2016-10-23 10:39:11.001 [DEBUG] [o.b.z.i.protocol.SerialMessage:115 ]- NODE 28: Creating empty message of class = SendData (0x13), type = Request (0x00)
2016-10-23 10:39:11.001 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:704 ]- NODE 28: Node advancer: STATIC_VALUES - queued 17 frames
2016-10-23 10:39:11.001 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 28: Node advancer - queued packet. Queue length is 17
2016-10-23 10:39:11.002 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 28: Sending REQUEST Message = 01 0D 00 13 1C 06 60 0D 01 01 85 05 25 1A 29 
2016-10-23 10:39:11.008 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 28: Sent Data successfully placed on stack.
2016-10-23 10:39:11.021 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 28: SendData Request. CallBack ID = 26, Status = Transmission complete and ACK received(0)
2016-10-23 10:39:11.967 [DEBUG] [ApplicationCommandMessageClass:41  ]- NODE 28: Application Command Request (ALIVE:STATIC_VALUES)
2016-10-23 10:39:11.967 [DEBUG] [ApplicationCommandMessageClass:146 ]- NODE 28: Incoming command class WAKE_UP (0x84)
2016-10-23 10:39:11.967 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:140 ]- NODE 28: Received Wake Up Request
2016-10-23 10:39:11.967 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:199 ]- NODE 28: Received WAKE_UP_NOTIFICATION
2016-10-23 10:39:11.967 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:449 ]- NODE 28: Is awake with 1 messages in the wake-up queue.
2016-10-23 10:39:11.967 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 28: Notifying event listeners: ZWaveWakeUpEvent
2016-10-23 10:39:11.968 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1140]- NODE 28: Wakeup during initialisation.
2016-10-23 10:39:11.968 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 28: Node advancer - STATIC_VALUES: queue length(17), free to send(false)
2016-10-23 10:39:11.968 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 28: Node advancer - queued packet. Queue length is 17
2016-10-23 10:39:14.444 [DEBUG] [ApplicationCommandMessageClass:41  ]- NODE 28: Application Command Request (ALIVE:STATIC_VALUES)
2016-10-23 10:39:14.445 [DEBUG] [ApplicationCommandMessageClass:146 ]- NODE 28: Incoming command class BASIC (0x20)
2016-10-23 10:39:14.445 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass:73  ]- NODE 28: Received Basic Request
2016-10-23 10:39:14.445 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass:77  ]- NODE 28: Basic Set sent to the controller will be processed as Basic Report
2016-10-23 10:39:14.445 [DEBUG] [z.i.p.c.ZWaveBasicCommandClass:106 ]- NODE 28: Basic report, value = 0xFF
2016-10-23 10:39:14.445 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 28: Notifying event listeners: ZWaveCommandClassValueEvent
2016-10-23 10:39:14.445 [DEBUG] [.z.internal.ZWaveActiveBinding:472 ]- NODE 28: Got a value event from Z-Wave network, endpoint = 0, command class = BASIC, value = 255
2016-10-23 10:39:14.445 [WARN ] [.z.internal.ZWaveActiveBinding:491 ]- NODE 28: No item bound for event, endpoint = 0, command class = BASIC, value = 255, ignoring.
2016-10-23 10:39:16.003 [DEBUG] [WaveController$ZWaveSendThread:1396]- NODE 28: Sending ABORT Message = 01 03 00 16 EA 
2016-10-23 10:39:16.003 [ERROR] [WaveController$ZWaveSendThread:1413]- NODE 28: Timeout while sending message. Requeueing - 2 attempts left!
2016-10-23 10:39:16.003 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:472 ]- NODE 28: Is sleeping
2016-10-23 10:39:16.003 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:260 ]- NODE 28: Putting message SendData in wakeup queue.
2016-10-23 10:39:16.003 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:260 ]- NODE 28: Putting message SendData in wakeup queue.
2016-10-23 10:39:16.003 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:255 ]- NODE 28: Message already on the wake-up queue. Removing original.
2016-10-23 10:39:16.004 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:260 ]- NODE 28: Putting message SendData in wakeup queue.
2016-10-23 10:39:16.004 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:255 ]- NODE 28: Message already on the wake-up queue. Removing original.
2016-10-23 10:39:16.004 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:260 ]- NODE 28: Putting message SendData in wakeup queue.
2016-10-23 10:42:12.308 [DEBUG] [ApplicationCommandMessageClass:41  ]- NODE 28: Application Command Request (ALIVE:STATIC_VALUES)
2016-10-23 10:42:12.308 [DEBUG] [ApplicationCommandMessageClass:146 ]- NODE 28: Incoming command class WAKE_UP (0x84)
2016-10-23 10:42:12.309 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:140 ]- NODE 28: Received Wake Up Request
2016-10-23 10:42:12.309 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:199 ]- NODE 28: Received WAKE_UP_NOTIFICATION
2016-10-23 10:42:12.309 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:449 ]- NODE 28: Is awake with 2 messages in the wake-up queue.
2016-10-23 10:42:12.309 [DEBUG] [b.z.i.protocol.ZWaveController:668 ]- NODE 28: Notifying event listeners: ZWaveWakeUpEvent
2016-10-23 10:42:12.309 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:1140]- NODE 28: Wakeup during initialisation.
2016-10-23 10:42:12.309 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:277 ]- NODE 28: Node advancer - STATIC_VALUES: queue length(17), free to send(false)
2016-10-23 10:42:12.310 [DEBUG] [z.i.p.i.ZWaveNodeStageAdvancer:250 ]- NODE 28: Node advancer - queued packet. Queue length is 17
2016-10-23 10:42:12.310 [DEBUG] [WaveController$ZWaveSendThread:1355]- NODE 28: Sending REQUEST Message = 01 0D 00 13 1C 06 60 0D 01 01 85 05 25 24 17 
2016-10-23 10:42:12.316 [DEBUG] [b.z.i.p.s.SendDataMessageClass:39  ]- NODE 28: Sent Data successfully placed on stack.
2016-10-23 10:42:12.329 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 28: SendData Request. CallBack ID = 36, Status = Transmission complete and ACK received(0)
2016-10-23 10:42:17.311 [ERROR] [WaveController$ZWaveSendThread:1413]- NODE 28: Timeout while sending message. Requeueing - 1 attempts left!
2016-10-23 10:42:17.311 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:472 ]- NODE 28: Is sleeping
2016-10-23 10:42:17.311 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:255 ]- NODE 28: Message already on the wake-up queue. Removing original.
2016-10-23 10:42:17.311 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:260 ]- NODE 28: Putting message SendData in wakeup queue.
2016-10-23 10:42:17.311 [DEBUG] [.i.p.c.ZWaveWakeUpCommandClass:260 ]- NODE 28: Putting message SendData in wakeup queue.

Avner · October 23, 2016, 6:07pm

I came across related post in Item Setup For ZWave HSM100
I also tried to change Assocoation Groups -> Association Group -> Node 1 -> Memeber
but the change never stick, and the initialisation systematically times out with warnings / errors:

grep -i "node 28:" logs/zwave.log | grep -i "error\|warn"
2016-10-23 01:01:39.847 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:141 ]- NODE 28: Error serializing from file: file does not exist.
2016-10-23 01:03:21.211 [ERROR] [WaveController$ZWaveSendThread:1413]- NODE 28: Timeout while sending message. Requeueing - 0 attempts left!
2016-10-23 01:03:44.010 [ERROR] [.z.i.config.ZWaveConfiguration:1124]- NODE 28: Error in doSet - no database found
2016-10-23 01:04:08.267 [ERROR] [.z.i.config.ZWaveConfiguration:1076]- NODE 28: Error in doAction - no database found
2016-10-23 01:06:21.707 [WARN ] [WaveController$ZWaveSendThread:1421]- NODE 28: Too many retries. Discarding message: Message: class = SendData (0x13), type = Request (0x00), payload = 1C 01 00 , callbackid = 72
2016-10-23 01:06:21.711 [ERROR] [b.z.i.p.s.SendDataMessageClass:43  ]- NODE 28: Sent Data was not placed on stack due to error 0.
2016-10-23 01:07:03.279 [WARN ] [b.z.i.p.s.SendDataMessageClass:78  ]- NODE 28: Already processed another send data request for this callback Id, ignoring.
2016-10-23 01:07:03.512 [WARN ] [b.z.i.p.s.SendDataMessageClass:78  ]- NODE 28: Already processed another send data request for this callback Id, ignoring.
2016-10-23 01:10:05.390 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:141 ]- NODE 28: Error serializing from file: file does not exist.
2016-10-23 01:10:05.639 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer:324 ]- NODE 28: Node advancer: Retries exceeded at MANUFACTURER
2016-10-23 01:10:30.176 [ERROR] [z.i.p.i.ZWaveNodeStageAdvancer:324 ]- NODE 28: Node advancer: Retries exceeded at MANUFACTURER

@chris, is there a way to increase the zwave timeout? Currently it is set to 5 secs?

tail -f logs/openhab.log | grep -i "timeout"
23:14:53.500 [INFO ] [b.z.i.protocol.ZWaveController:166  ] - Z-Wave timeout is set to 5000ms. Soft reset is false.

If it helps, here is the node in habmin:

Avner · October 30, 2016, 4:43am

Still no luck.
I tried following the advice in https://community.openhab.org/t/hsm100-missing-zwave-node-xml-file/15637/7 and installed an earlier version of opnehab 1.8.0
I’m still getting timeout errors, and the node xml file is not created in etc/zwave.
When I wake up the device (by physically pressing the button on the motion sensor device) I do get indication of communication.but it always ends up with

I’m out of ideas…Any advise on what to do next will be appreciated.

Thanks,
Avner

2016-10-29 21:21:15.937 [DEBUG] [b.z.i.p.s.SendDataMessageClass:74  ]- NODE 29: SendData Request. CallBack ID = 86, Status = Transmission complete and ACK received(0)
2016-10-29 21:21:15.937 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:83  ]- Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 1D 06 60 0D 01 01 77 02 , callbackid = 86
2016-10-29 21:21:15.937 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:84  ]- Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 56 00 , callbackid = 0
2016-10-29 21:21:15.937 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:85  ]- Checking transaction complete: Sent message Message: class = SendData (0x13), type = Request (0x00), payload = 1D 06 60 0D 01 01 77 02 , callbackid = 86
2016-10-29 21:21:15.937 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:96  ]- Checking transaction complete: Recv message Message: class = SendData (0x13), type = Request (0x00), payload = 56 00 , callbackid = 0
2016-10-29 21:21:15.938 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:107 ]- Checking transaction complete: class=SendData, callback id=86, expected=ApplicationCommandHandler, cancelled=false      mismatch
2016-10-29 21:21:20.917 [ERROR] [WaveController$ZWaveSendThread:1413]- NODE 29: Timeout while sending message. Requeueing - 2 attempts left!
2016-10-29 21:21:20.917 [ERROR] [b.z.i.p.s.SendDataMessageClass:159 ]- NODE 29: Got an error while sending data. Resending message.
...