Closed grzech1983 closed 9 years ago
cdjackson
commented
9 years ago Hi, I can’t really tell anything from this log - I really need to see what the device is doing, so need the debug from the binding initialisation. If you can delete the XML and restart the binding that would be useful.
Chris
grzech1983
commented
9 years ago Log with "NODE 72" grep will be enough?
2015-02-04 08:16:47.956 INFO o.o.b.z.i.p.s.SerialApiGetInitDataMessageClass[:57]- NODE 72: Node found 2015-02-04 08:17:06.480 DEBUG o.o.b.z.i.p.i.ZWaveNodeSerializer[:129]- NODE 72: Serializing from file etc/zwave/node72.xml 2015-02-04 08:17:06.482 DEBUG o.o.b.z.i.p.i.ZWaveNodeSerializer[:132]- NODE 72: Error serializing from file: file does not exist. 2015-02-04 08:17:06.484 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:252]- NODE 72: Node advancer - EMPTYNODE: queue length(0), free to send(true) 2015-02-04 08:17:06.486 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false) 2015-02-04 08:17:06.488 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:315]- NODE 72: Node advancer: Initialisation starting 2015-02-04 08:17:06.491 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:733]- NODE 72: Node advancer - advancing to PROTOINFO 2015-02-04 08:17:06.493 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true) 2015-02-04 08:17:06.495 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:324]- NODE 72: Node advancer: PROTOINFO - send IdentifyNode 2015-02-04 08:17:06.501 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:225]- NODE 72: Node advancer - queued packet. Queue length is 1 2015-02-04 08:17:07.547 INFO o.o.b.z.i.p.s.SerialApiGetInitDataMessageClass[:57]- NODE 72: Node found 2015-02-04 08:17:28.695 DEBUG o.o.b.z.i.p.i.ZWaveNodeSerializer[:129]- NODE 72: Serializing from file etc/zwave/node72.xml 2015-02-04 08:17:28.703 DEBUG o.o.b.z.i.p.i.ZWaveNodeSerializer[:132]- NODE 72: Error serializing from file: file does not exist. 2015-02-04 08:17:28.709 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:252]- NODE 72: Node advancer - EMPTYNODE: queue length(0), free to send(true) 2015-02-04 08:17:28.711 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - EMPTYNODE try 1: stageAdvanced(false) 2015-02-04 08:17:28.716 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:315]- NODE 72: Node advancer: Initialisation starting 2015-02-04 08:17:28.724 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:733]- NODE 72: Node advancer - advancing to PROTOINFO 2015-02-04 08:17:28.725 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - PROTOINFO try 0: stageAdvanced(true) 2015-02-04 08:17:28.735 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:324]- NODE 72: Node advancer: PROTOINFO - send IdentifyNode 2015-02-04 08:17:28.758 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:225]- NODE 72: Node advancer - queued packet. Queue length is 1 2015-02-04 08:17:40.848 DEBUG o.o.b.z.i.p.s.IdentifyNodeMessageClass[:52]- NODE 72: ProtocolInfo 2015-02-04 08:17:40.850 DEBUG o.o.b.z.i.p.s.IdentifyNodeMessageClass[:61]- NODE 72: Listening = true 2015-02-04 08:17:40.851 DEBUG o.o.b.z.i.p.s.IdentifyNodeMessageClass[:62]- NODE 72: Routing = true 2015-02-04 08:17:40.852 DEBUG o.o.b.z.i.p.s.IdentifyNodeMessageClass[:63]- NODE 72: Version = 3 2015-02-04 08:17:40.853 DEBUG o.o.b.z.i.p.s.IdentifyNodeMessageClass[:64]- NODE 72: FLIRS = false 2015-02-04 08:17:40.855 DEBUG o.o.b.z.i.p.s.IdentifyNodeMessageClass[:76]- NODE 72: Basic = Routing Slave 2015-02-04 08:17:40.856 DEBUG o.o.b.z.i.p.s.IdentifyNodeMessageClass[:83]- NODE 72: Generic = Binary Sensor 2015-02-04 08:17:40.857 DEBUG o.o.b.z.i.p.s.IdentifyNodeMessageClass[:90]- NODE 72: Specific = Routing Binary Sensor 2015-02-04 08:17:40.858 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class NO_OPERATION 2015-02-04 08:17:40.859 DEBUG o.o.b.z.i.protocol.ZWaveNode[:499]- NODE 72: Adding command class NO_OPERATION to the list of supported command classes. 2015-02-04 08:17:40.861 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class BASIC 2015-02-04 08:17:40.862 DEBUG o.o.b.z.i.protocol.ZWaveNode[:499]- NODE 72: Adding command class BASIC to the list of supported command classes. 2015-02-04 08:17:40.865 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class SENSOR_BINARY 2015-02-04 08:17:40.866 DEBUG o.o.b.z.i.protocol.ZWaveNode[:499]- NODE 72: Adding command class SENSOR_BINARY to the list of supported command classes. 2015-02-04 08:17:40.886 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true) 2015-02-04 08:17:40.888 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:17:40.890 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:192]- NODE 72: Node advancer - message removed from queue. Queue size now 0. 2015-02-04 08:17:40.893 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:252]- NODE 72: Node advancer - PROTOINFO: queue length(0), free to send(true) 2015-02-04 08:17:40.894 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false) 2015-02-04 08:17:40.897 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:733]- NODE 72: Node advancer - advancing to NEIGHBORS 2015-02-04 08:17:40.899 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true) 2015-02-04 08:17:40.901 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:334]- NODE 72: Node advancer: NEIGHBORS - send RoutingInfo 2015-02-04 08:17:40.902 DEBUG o.o.b.z.i.p.s.GetRoutingInfoMessageClass[:29]- NODE 72: Request routing info 2015-02-04 08:17:40.909 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:225]- NODE 72: Node advancer - queued packet. Queue length is 1 2015-02-04 08:17:40.915 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - PROTOINFO: Transaction complete (IdentifyNode:Request) success(true) 2015-02-04 08:17:40.916 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:17:40.918 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:192]- NODE 72: Node advancer - message removed from queue. Queue size now 0. 2015-02-04 08:17:40.919 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:252]- NODE 72: Node advancer - PROTOINFO: queue length(0), free to send(true) 2015-02-04 08:17:40.921 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - PROTOINFO try 1: stageAdvanced(false) 2015-02-04 08:17:40.922 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:733]- NODE 72: Node advancer - advancing to NEIGHBORS 2015-02-04 08:17:40.924 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - NEIGHBORS try 0: stageAdvanced(true) 2015-02-04 08:17:40.925 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:334]- NODE 72: Node advancer: NEIGHBORS - send RoutingInfo 2015-02-04 08:17:40.927 DEBUG o.o.b.z.i.p.s.GetRoutingInfoMessageClass[:29]- NODE 72: Request routing info 2015-02-04 08:17:40.934 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:225]- NODE 72: Node advancer - queued packet. Queue length is 1 2015-02-04 08:17:45.174 DEBUG o.o.b.z.i.p.s.IdentifyNodeMessageClass[:52]- NODE 72: ProtocolInfo 2015-02-04 08:17:45.175 DEBUG o.o.b.z.i.p.s.IdentifyNodeMessageClass[:61]- NODE 72: Listening = true 2015-02-04 08:17:45.176 DEBUG o.o.b.z.i.p.s.IdentifyNodeMessageClass[:62]- NODE 72: Routing = true 2015-02-04 08:17:45.177 DEBUG o.o.b.z.i.p.s.IdentifyNodeMessageClass[:63]- NODE 72: Version = 3 2015-02-04 08:17:45.178 DEBUG o.o.b.z.i.p.s.IdentifyNodeMessageClass[:64]- NODE 72: FLIRS = false 2015-02-04 08:17:45.179 DEBUG o.o.b.z.i.p.s.IdentifyNodeMessageClass[:76]- NODE 72: Basic = Routing Slave 2015-02-04 08:17:45.181 DEBUG o.o.b.z.i.p.s.IdentifyNodeMessageClass[:83]- NODE 72: Generic = Binary Sensor 2015-02-04 08:17:45.182 DEBUG o.o.b.z.i.p.s.IdentifyNodeMessageClass[:90]- NODE 72: Specific = Routing Binary Sensor 2015-02-04 08:17:45.183 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class NO_OPERATION 2015-02-04 08:17:45.184 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class BASIC 2015-02-04 08:17:45.186 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class SENSOR_BINARY 2015-02-04 08:17:45.205 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - NEIGHBORS: Transaction complete (IdentifyNode:Request) success(true) 2015-02-04 08:17:45.207 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:17:45.210 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - NEIGHBORS: Transaction complete (IdentifyNode:Request) success(true) 2015-02-04 08:17:45.212 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:17:45.488 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:17:45.490 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:17:45.498 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:17:45.510 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:17:45.636 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:17:45.638 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:17:45.644 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:17:45.655 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:17:50.126 DEBUG o.o.b.z.i.p.s.GetRoutingInfoMessageClass[:47]- NODE 72: Got NodeRoutingInfo request. 2015-02-04 08:17:50.127 DEBUG o.o.b.z.i.p.s.GetRoutingInfoMessageClass[:78]- NODE 72: Neighbor nodes: 8 10 13 14 15 16 17 18 27 31 32 44 59 62 63 68 69 70 74 2015-02-04 08:17:50.133 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true) 2015-02-04 08:17:50.134 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:17:50.134 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:192]- NODE 72: Node advancer - message removed from queue. Queue size now 0. 2015-02-04 08:17:50.135 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:252]- NODE 72: Node advancer - NEIGHBORS: queue length(0), free to send(true) 2015-02-04 08:17:50.136 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false) 2015-02-04 08:17:50.137 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:733]- NODE 72: Node advancer - advancing to FAILED_CHECK 2015-02-04 08:17:50.138 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true) 2015-02-04 08:17:50.139 DEBUG o.o.b.z.i.p.s.IsFailedNodeMessageClass[:31]- NODE 72: Requesting IsFailedNode status from controller. 2015-02-04 08:17:50.141 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:225]- NODE 72: Node advancer - queued packet. Queue length is 1 2015-02-04 08:17:50.142 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - NEIGHBORS: Transaction complete (GetRoutingInfo:Request) success(true) 2015-02-04 08:17:50.143 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:17:50.144 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:192]- NODE 72: Node advancer - message removed from queue. Queue size now 0. 2015-02-04 08:17:50.145 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:252]- NODE 72: Node advancer - NEIGHBORS: queue length(0), free to send(true) 2015-02-04 08:17:50.146 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - NEIGHBORS try 1: stageAdvanced(false) 2015-02-04 08:17:50.147 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:733]- NODE 72: Node advancer - advancing to FAILED_CHECK 2015-02-04 08:17:50.147 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - FAILED_CHECK try 0: stageAdvanced(true) 2015-02-04 08:17:50.148 DEBUG o.o.b.z.i.p.s.IsFailedNodeMessageClass[:31]- NODE 72: Requesting IsFailedNode status from controller. 2015-02-04 08:17:50.151 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:225]- NODE 72: Node advancer - queued packet. Queue length is 1 2015-02-04 08:17:50.172 DEBUG o.o.b.z.i.p.s.GetRoutingInfoMessageClass[:47]- NODE 72: Got NodeRoutingInfo request. 2015-02-04 08:17:50.172 DEBUG o.o.b.z.i.p.s.GetRoutingInfoMessageClass[:78]- NODE 72: Neighbor nodes: 8 10 13 14 15 16 17 18 27 31 32 44 59 62 63 68 69 70 74 2015-02-04 08:17:50.180 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - FAILED_CHECK: Transaction complete (GetRoutingInfo:Request) success(true) 2015-02-04 08:17:50.181 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:17:50.183 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - FAILED_CHECK: Transaction complete (GetRoutingInfo:Request) success(true) 2015-02-04 08:17:50.184 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:17:53.127 DEBUG o.o.b.z.i.p.s.IsFailedNodeMessageClass[:54]- NODE 72: Is currently marked as healthy by the controller 2015-02-04 08:17:53.135 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true) 2015-02-04 08:17:53.136 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:17:53.137 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:192]- NODE 72: Node advancer - message removed from queue. Queue size now 0. 2015-02-04 08:17:53.138 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:252]- NODE 72: Node advancer - FAILED_CHECK: queue length(0), free to send(true) 2015-02-04 08:17:53.140 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false) 2015-02-04 08:17:53.141 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:733]- NODE 72: Node advancer - advancing to WAIT 2015-02-04 08:17:53.142 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - WAIT try 0: stageAdvanced(true) 2015-02-04 08:17:53.144 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:357]- NODE 72: Node advancer: WAIT - Listening=false, FrequentlyListening=false 2015-02-04 08:17:53.145 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:375]- NODE 72: Node advancer: WAIT - Still waiting! 2015-02-04 08:17:53.146 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - FAILED_CHECK: Transaction complete (IsFailedNodeID:Request) success(true) 2015-02-04 08:17:53.147 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:17:53.149 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:192]- NODE 72: Node advancer - message removed from queue. Queue size now 0. 2015-02-04 08:17:53.150 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:252]- NODE 72: Node advancer - FAILED_CHECK: queue length(0), free to send(true) 2015-02-04 08:17:53.151 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - FAILED_CHECK try 1: stageAdvanced(false) 2015-02-04 08:17:53.153 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:733]- NODE 72: Node advancer - advancing to WAIT 2015-02-04 08:17:53.154 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - WAIT try 0: stageAdvanced(true) 2015-02-04 08:17:53.155 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:357]- NODE 72: Node advancer: WAIT - Listening=true, FrequentlyListening=false 2015-02-04 08:17:53.156 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:361]- NODE 72: Node advancer: WAIT - Advancing 2015-02-04 08:17:53.158 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:733]- NODE 72: Node advancer - advancing to PING 2015-02-04 08:17:53.159 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - PING try 0: stageAdvanced(true) 2015-02-04 08:17:53.160 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:394]- NODE 72: Node advancer: PING - send NoOperation 2015-02-04 08:17:53.161 DEBUG o.o.b.z.i.p.c.ZWaveNoOperationCommandClass[:72]- NODE 72: Creating new message for command No Operation 2015-02-04 08:17:53.162 DEBUG o.o.b.z.i.p.SerialMessage[:109]- NODE 72: Creating empty message of class = SendData (0x13), type = Request (0x00) 2015-02-04 08:17:53.166 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:225]- NODE 72: Node advancer - queued packet. Queue length is 1 2015-02-04 08:17:53.181 DEBUG o.o.b.z.i.p.s.IsFailedNodeMessageClass[:54]- NODE 72: Is currently marked as healthy by the controller 2015-02-04 08:17:53.198 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - WAIT: Transaction complete (IsFailedNodeID:Request) success(true) 2015-02-04 08:17:53.199 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:17:53.201 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - PING: Transaction complete (IsFailedNodeID:Request) success(true) 2015-02-04 08:17:53.202 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:18:01.835 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:18:01.836 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:18:01.839 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:18:01.844 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:18:04.671 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:18:04.672 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:18:04.675 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:18:04.680 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:19:43.517 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:19:43.517 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:19:43.520 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:19:43.524 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:19:46.413 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:19:46.414 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:19:46.418 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:19:46.424 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:20:00.139 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:20:00.140 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:20:00.146 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:20:00.156 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:20:21.452 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:20:21.453 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:20:21.456 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:20:21.461 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:20:30.390 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:20:30.390 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:20:30.393 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:20:30.397 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:20:50.216 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:20:50.217 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:20:50.220 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:20:50.224 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:20:57.960 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:20:57.960 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:20:57.963 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:20:57.967 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:21:00.505 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:21:00.505 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:21:00.507 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:21:00.511 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:21:03.099 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:21:03.100 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:21:03.102 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:21:03.106 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:21:10.408 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:21:10.409 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:21:10.411 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:21:10.415 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:21:12.991 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:21:12.992 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:21:12.994 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:21:12.998 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:21:15.409 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:21:15.409 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:21:15.412 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:21:15.416 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:21:18.112 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:21:18.113 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:21:18.117 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:21:18.124 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:21:20.696 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:21:20.696 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:21:20.700 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:21:20.705 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:21:26.947 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:21:26.947 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:21:26.950 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:21:26.956 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:21:29.195 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:21:29.195 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:21:29.198 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:21:29.203 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:21:41.844 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:21:41.844 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:21:41.847 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:21:41.851 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:21:44.431 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:21:44.432 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:21:44.433 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:21:44.436 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:21:47.055 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:21:47.055 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:21:47.058 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:21:47.060 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:21:50.089 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:21:50.090 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:21:50.094 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:21:50.098 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:21:51.799 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:21:51.799 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:21:51.802 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:21:51.805 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:21:52.934 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:21:52.934 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:21:52.937 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:21:52.940 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:22:49.907 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:22:49.908 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:22:49.911 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:22:49.914 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:22:52.434 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:22:52.435 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:22:52.437 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:22:52.440 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:22:55.971 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:22:55.972 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:22:55.975 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:22:55.978 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:22:58.180 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:22:58.180 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:22:58.183 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:22:58.186 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:23:14.526 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:23:14.526 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:23:14.528 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:23:14.530 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:23:17.243 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:23:17.244 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:23:17.247 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:23:17.250 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:23:19.859 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:23:19.860 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:23:19.862 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:23:19.864 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:23:22.335 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:23:22.336 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:23:22.338 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:23:22.341 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:23:24.470 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:23:24.470 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:23:24.472 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:23:24.474 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:23:26.559 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:23:26.560 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:23:26.562 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:23:26.564 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:23:46.622 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:23:46.622 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:23:46.626 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:23:46.629 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:23:56.731 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:23:56.731 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:23:56.733 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:23:56.735 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:24:00.789 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:24:00.790 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:24:00.791 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:24:00.794 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:24:03.916 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:24:03.916 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:24:03.917 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:24:03.919 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:24:06.929 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:24:06.930 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:24:06.933 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:24:06.936 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:24:14.268 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:24:14.268 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:24:14.270 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:24:14.271 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:24:24.922 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:24:24.923 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:24:24.925 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:24:24.928 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:24:50.343 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:24:50.343 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:24:50.346 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:24:50.348 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:26:59.270 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:26:59.270 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:26:59.271 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:26:59.272 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:27:02.484 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:27:02.484 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:27:02.486 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:27:02.487 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:27:36.963 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:27:36.963 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:27:36.965 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:27:36.966 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:28:03.098 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:28:03.098 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:28:03.100 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:28:03.102 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:28:04.896 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:28:04.897 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:28:04.899 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:28:04.901 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:28:06.953 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:28:06.953 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:28:06.955 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:28:06.957 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:28:17.954 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:28:17.955 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:28:17.957 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:28:17.959 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:28:30.148 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:28:30.148 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:28:30.150 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:28:30.151 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:28:45.408 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:28:45.408 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:28:45.410 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:28:45.412 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:28:47.840 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:28:47.840 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:28:47.842 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:28:47.843 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:28:55.329 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:28:55.329 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:28:55.331 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:28:55.332 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:28:57.707 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:28:57.707 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:28:57.708 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:28:57.710 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:29:21.780 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:29:21.780 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:29:21.781 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:29:21.782 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:29:26.850 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_RH_AZH is not completed initialisation 2015-02-04 08:29:26.850 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_T_AZH is not completed initialisation 2015-02-04 08:29:26.851 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_M_AZH is not completed initialisation 2015-02-04 08:29:26.852 DEBUG o.o.b.z.i.ZWaveActiveBinding[:190]- NODE 72: Polling list: item Aeon_L_AZH is not completed initialisation 2015-02-04 08:29:26.942 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1350]- NODE 72: Sending REQUEST Message = 01 08 00 13 48 01 00 25 46 CE 2015-02-04 08:29:27.233 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:39]- NODE 72: Sent Data successfully placed on stack. 2015-02-04 08:29:28.706 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:75]- NODE 72: SendData Request. CallBack ID = 70, Status = Transmission complete and ACK received(0) 2015-02-04 08:29:28.709 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - WAIT: Transaction complete (SendData:Request) success(true) 2015-02-04 08:29:28.710 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:29:28.710 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - PING: Transaction complete (SendData:Request) success(true) 2015-02-04 08:29:28.711 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:29:28.711 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:192]- NODE 72: Node advancer - message removed from queue. Queue size now 0. 2015-02-04 08:29:28.712 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:252]- NODE 72: Node advancer - PING: queue length(0), free to send(true) 2015-02-04 08:29:28.713 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - PING try 1: stageAdvanced(false) 2015-02-04 08:29:28.713 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:733]- NODE 72: Node advancer - advancing to DETAILS 2015-02-04 08:29:28.714 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - DETAILS try 0: stageAdvanced(true) 2015-02-04 08:29:28.714 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:423]- NODE 72: Node advancer: DETAILS - send RequestNodeInfo 2015-02-04 08:29:28.716 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:225]- NODE 72: Node advancer - queued packet. Queue length is 1 2015-02-04 08:29:28.717 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1407]- NODE 72: Response processed after 1774ms/4320ms. 2015-02-04 08:29:30.445 DEBUG o.o.b.z.i.p.s.ApplicationUpdateMessageClass[:44]- NODE 72: Application update request. Node information received. 2015-02-04 08:29:30.446 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class SENSOR_BINARY 2015-02-04 08:29:30.447 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class SENSOR_MULTILEVEL 2015-02-04 08:29:30.447 DEBUG o.o.b.z.i.protocol.ZWaveNode[:499]- NODE 72: Adding command class SENSOR_MULTILEVEL to the list of supported command classes. 2015-02-04 08:29:30.448 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class BATTERY 2015-02-04 08:29:30.450 DEBUG o.o.b.z.i.protocol.ZWaveNode[:499]- NODE 72: Adding command class BATTERY to the list of supported command classes. 2015-02-04 08:29:30.451 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class WAKE_UP 2015-02-04 08:29:30.452 DEBUG o.o.b.z.i.protocol.ZWaveNode[:499]- NODE 72: Adding command class WAKE_UP to the list of supported command classes. 2015-02-04 08:29:30.452 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class CONFIGURATION 2015-02-04 08:29:30.453 DEBUG o.o.b.z.i.protocol.ZWaveNode[:499]- NODE 72: Adding command class CONFIGURATION to the list of supported command classes. 2015-02-04 08:29:30.454 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class ASSOCIATION 2015-02-04 08:29:30.456 DEBUG o.o.b.z.i.protocol.ZWaveNode[:499]- NODE 72: Adding command class ASSOCIATION to the list of supported command classes. 2015-02-04 08:29:30.456 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class MANUFACTURER_SPECIFIC 2015-02-04 08:29:30.458 DEBUG o.o.b.z.i.protocol.ZWaveNode[:499]- NODE 72: Adding command class MANUFACTURER_SPECIFIC to the list of supported command classes. 2015-02-04 08:29:30.459 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class VERSION 2015-02-04 08:29:30.461 DEBUG o.o.b.z.i.protocol.ZWaveNode[:499]- NODE 72: Adding command class VERSION to the list of supported command classes. 2015-02-04 08:29:30.462 DEBUG o.o.b.z.i.p.c.ZWaveWakeUpCommandClass[:404]- NODE 72: Is awake with 0 messages in the wake-up queue. 2015-02-04 08:29:30.463 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:901]- NODE 72: Wakeup during initialisation. 2015-02-04 08:29:30.464 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:252]- NODE 72: Node advancer - WAIT: queue length(0), free to send(true) 2015-02-04 08:29:30.464 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - WAIT try 1: stageAdvanced(false) 2015-02-04 08:29:30.465 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:357]- NODE 72: Node advancer: WAIT - Listening=false, FrequentlyListening=false 2015-02-04 08:29:30.466 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:375]- NODE 72: Node advancer: WAIT - Still waiting! 2015-02-04 08:29:30.466 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:901]- NODE 72: Wakeup during initialisation. 2015-02-04 08:29:30.467 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:252]- NODE 72: Node advancer - DETAILS: queue length(1), free to send(false) 2015-02-04 08:29:30.468 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:225]- NODE 72: Node advancer - queued packet. Queue length is 1 2015-02-04 08:29:30.471 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - WAIT: Transaction complete (RequestNodeInfo:Request) success(true) 2015-02-04 08:29:30.471 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:29:30.471 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - DETAILS: Transaction complete (RequestNodeInfo:Request) success(true) 2015-02-04 08:29:30.472 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:29:30.472 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:192]- NODE 72: Node advancer - message removed from queue. Queue size now 0. 2015-02-04 08:29:30.473 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:252]- NODE 72: Node advancer - DETAILS: queue length(0), free to send(true) 2015-02-04 08:29:30.473 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - DETAILS try 1: stageAdvanced(false) 2015-02-04 08:29:30.474 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:419]- NODE 72: Node advancer: received RequestNodeInfo 2015-02-04 08:29:30.474 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:733]- NODE 72: Node advancer - advancing to MANUFACTURER 2015-02-04 08:29:30.475 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - MANUFACTURER try 0: stageAdvanced(true) 2015-02-04 08:29:30.476 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:441]- NODE 72: Node advancer: MANUFACTURER - send ManufacturerSpecific 2015-02-04 08:29:30.476 DEBUG o.o.b.z.i.p.c.ZWaveManufacturerSpecificCommandClass[:101]- NODE 72: Creating new message for command MANUFACTURER_SPECIFIC_GET 2015-02-04 08:29:30.477 DEBUG o.o.b.z.i.p.SerialMessage[:109]- NODE 72: Creating empty message of class = SendData (0x13), type = Request (0x00) 2015-02-04 08:29:30.478 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:225]- NODE 72: Node advancer - queued packet. Queue length is 1 2015-02-04 08:29:30.684 DEBUG o.o.b.z.i.p.s.ApplicationUpdateMessageClass[:44]- NODE 72: Application update request. Node information received. 2015-02-04 08:29:30.684 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class SENSOR_BINARY 2015-02-04 08:29:30.685 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class SENSOR_MULTILEVEL 2015-02-04 08:29:30.686 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class BATTERY 2015-02-04 08:29:30.687 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class WAKE_UP 2015-02-04 08:29:30.688 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class CONFIGURATION 2015-02-04 08:29:30.689 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class ASSOCIATION 2015-02-04 08:29:30.690 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class MANUFACTURER_SPECIFIC 2015-02-04 08:29:30.690 DEBUG o.o.b.z.i.p.c.ZWaveCommandClass[:220]- NODE 72: Creating new instance of command class VERSION 2015-02-04 08:29:30.691 DEBUG o.o.b.z.i.p.c.ZWaveWakeUpCommandClass[:404]- NODE 72: Is awake with 0 messages in the wake-up queue. 2015-02-04 08:29:30.692 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:901]- NODE 72: Wakeup during initialisation. 2015-02-04 08:29:30.692 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:252]- NODE 72: Node advancer - WAIT: queue length(0), free to send(true) 2015-02-04 08:29:30.693 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:310]- NODE 72: Node advancer: loop - WAIT try 2: stageAdvanced(false) 2015-02-04 08:29:30.693 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:357]- NODE 72: Node advancer: WAIT - Listening=false, FrequentlyListening=false 2015-02-04 08:29:30.694 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:375]- NODE 72: Node advancer: WAIT - Still waiting! 2015-02-04 08:29:30.694 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:901]- NODE 72: Wakeup during initialisation. 2015-02-04 08:29:30.695 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:252]- NODE 72: Node advancer - MANUFACTURER: queue length(1), free to send(false) 2015-02-04 08:29:30.696 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:225]- NODE 72: Node advancer - queued packet. Queue length is 1 2015-02-04 08:29:30.699 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - WAIT: Transaction complete (RequestNodeInfo:Request) success(true) 2015-02-04 08:29:30.699 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:29:30.700 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - MANUFACTURER: Transaction complete (RequestNodeInfo:Request) success(true) 2015-02-04 08:29:30.700 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:29:30.702 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1350]- NODE 72: Sending REQUEST Message = 01 09 00 13 48 02 72 04 25 E9 15 2015-02-04 08:29:30.710 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:39]- NODE 72: Sent Data successfully placed on stack. 2015-02-04 08:29:32.474 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:75]- NODE 72: SendData Request. CallBack ID = 233, Status = Transmission complete, no ACK received(1) 2015-02-04 08:29:32.474 ERROR o.o.b.z.i.p.s.SendDataMessageClass[:163]- NODE 72: Got an error while sending data. Resending message. 2015-02-04 08:29:32.477 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - WAIT: Transaction complete (SendData:Request) success(false) 2015-02-04 08:29:32.477 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - MANUFACTURER: Transaction complete (SendData:Request) success(false) 2015-02-04 08:29:32.478 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1407]- NODE 72: Response processed after 1775ms/4320ms. 2015-02-04 08:29:32.480 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1350]- NODE 72: Sending REQUEST Message = 01 09 00 13 48 02 72 04 25 EA 16 2015-02-04 08:29:32.771 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:39]- NODE 72: Sent Data successfully placed on stack. 2015-02-04 08:29:34.478 DEBUG o.o.b.z.i.p.c.ZWaveWakeUpCommandClass[:486]- NODE 72: No more messages, go back to sleep 2015-02-04 08:29:34.478 DEBUG o.o.b.z.i.p.c.ZWaveWakeUpCommandClass[:198]- NODE 72: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION 2015-02-04 08:29:34.479 DEBUG o.o.b.z.i.p.SerialMessage[:109]- NODE 72: Creating empty message of class = SendData (0x13), type = Request (0x00) 2015-02-04 08:29:34.936 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:75]- NODE 72: SendData Request. CallBack ID = 234, Status = Transmission complete, no ACK received(1) 2015-02-04 08:29:34.936 ERROR o.o.b.z.i.p.s.SendDataMessageClass[:163]- NODE 72: Got an error while sending data. Resending message. 2015-02-04 08:29:34.938 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - WAIT: Transaction complete (SendData:Request) success(false) 2015-02-04 08:29:34.939 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - MANUFACTURER: Transaction complete (SendData:Request) success(false) 2015-02-04 08:29:34.939 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1407]- NODE 72: Response processed after 2459ms/4320ms. 2015-02-04 08:29:34.941 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1350]- NODE 72: Sending REQUEST Message = 01 09 00 13 48 02 72 04 25 EC 10 2015-02-04 08:29:35.193 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:39]- NODE 72: Sent Data successfully placed on stack. 2015-02-04 08:29:36.939 DEBUG o.o.b.z.i.p.c.ZWaveWakeUpCommandClass[:486]- NODE 72: No more messages, go back to sleep 2015-02-04 08:29:36.940 DEBUG o.o.b.z.i.p.c.ZWaveWakeUpCommandClass[:198]- NODE 72: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION 2015-02-04 08:29:36.941 DEBUG o.o.b.z.i.p.SerialMessage[:109]- NODE 72: Creating empty message of class = SendData (0x13), type = Request (0x00) 2015-02-04 08:29:37.158 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:75]- NODE 72: SendData Request. CallBack ID = 236, Status = Transmission complete, no ACK received(1) 2015-02-04 08:29:37.159 DEBUG o.o.b.z.i.protocol.ZWaveNode[:234]- NODE 72: Node is DEAD. 2015-02-04 08:29:37.159 DEBUG o.o.b.z.i.protocol.ZWaveNode[:244]- NODE 72: Initialisation incomplete, not signalling state change. 2015-02-04 08:29:37.160 ERROR o.o.b.z.i.p.s.SendDataMessageClass[:142]- NODE 72: Node is DEAD. Dropping message. 2015-02-04 08:29:37.161 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - WAIT: Transaction complete (SendData:Request) success(false) 2015-02-04 08:29:37.162 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - MANUFACTURER: Transaction complete (SendData:Request) success(false) 2015-02-04 08:29:37.163 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1407]- NODE 72: Response processed after 2221ms/4320ms. 2015-02-04 08:29:37.165 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1350]- NODE 72: Sending REQUEST Message = 01 09 00 13 48 02 72 04 25 EC 10 2015-02-04 08:29:37.419 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:39]- NODE 72: Sent Data successfully placed on stack. 2015-02-04 08:29:38.998 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:75]- NODE 72: SendData Request. CallBack ID = 236, Status = Transmission complete, no ACK received(1) 2015-02-04 08:29:38.999 ERROR o.o.b.z.i.p.s.SendDataMessageClass[:142]- NODE 72: Node is DEAD. Dropping message. 2015-02-04 08:29:39.000 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - WAIT: Transaction complete (SendData:Request) success(false) 2015-02-04 08:29:39.000 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - MANUFACTURER: Transaction complete (SendData:Request) success(false) 2015-02-04 08:29:39.001 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1407]- NODE 72: Response processed after 1836ms/4320ms. 2015-02-04 08:29:41.000 DEBUG o.o.b.z.i.p.c.ZWaveWakeUpCommandClass[:486]- NODE 72: No more messages, go back to sleep 2015-02-04 08:29:41.000 DEBUG o.o.b.z.i.p.c.ZWaveWakeUpCommandClass[:198]- NODE 72: Creating new message for application command WAKE_UP_NO_MORE_INFORMATION 2015-02-04 08:29:41.001 DEBUG o.o.b.z.i.p.SerialMessage[:109]- NODE 72: Creating empty message of class = SendData (0x13), type = Request (0x00) 2015-02-04 08:30:03.772 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1350]- NODE 72: Sending REQUEST Message = 01 09 00 13 48 02 84 08 25 EB ED 2015-02-04 08:30:03.866 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:39]- NODE 72: Sent Data successfully placed on stack. 2015-02-04 08:30:06.208 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:75]- NODE 72: SendData Request. CallBack ID = 235, Status = Transmission complete, no ACK received(1) 2015-02-04 08:30:06.211 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:109]- NODE 72: WAKE_UP_NO_MORE_INFORMATION. Treated as ACK. 2015-02-04 08:30:06.213 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - WAIT: Transaction complete (SendData:Request) success(true) 2015-02-04 08:30:06.213 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:30:06.214 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - MANUFACTURER: Transaction complete (SendData:Request) success(true) 2015-02-04 08:30:06.214 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:30:06.214 DEBUG o.o.b.z.i.p.c.ZWaveWakeUpCommandClass[:368]- NODE 72: Went to sleep 2015-02-04 08:30:06.215 DEBUG o.o.b.z.i.p.c.ZWaveWakeUpCommandClass[:423]- NODE 72: Is sleeping 2015-02-04 08:30:06.215 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1407]- NODE 72: Response processed after 2442ms/4320ms. 2015-02-04 08:30:06.217 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1350]- NODE 72: Sending REQUEST Message = 01 09 00 13 48 02 84 08 25 ED EB 2015-02-04 08:30:06.508 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:39]- NODE 72: Sent Data successfully placed on stack. 2015-02-04 08:30:08.528 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:75]- NODE 72: SendData Request. CallBack ID = 237, Status = Transmission complete, no ACK received(1) 2015-02-04 08:30:08.530 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:109]- NODE 72: WAKE_UP_NO_MORE_INFORMATION. Treated as ACK. 2015-02-04 08:30:08.532 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - WAIT: Transaction complete (SendData:Request) success(true) 2015-02-04 08:30:08.532 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:30:08.532 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - MANUFACTURER: Transaction complete (SendData:Request) success(true) 2015-02-04 08:30:08.533 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:30:08.533 DEBUG o.o.b.z.i.p.c.ZWaveWakeUpCommandClass[:368]- NODE 72: Went to sleep 2015-02-04 08:30:08.533 DEBUG o.o.b.z.i.p.c.ZWaveWakeUpCommandClass[:423]- NODE 72: Is sleeping 2015-02-04 08:30:08.534 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1407]- NODE 72: Response processed after 2317ms/4320ms. 2015-02-04 08:30:08.535 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1350]- NODE 72: Sending REQUEST Message = 01 09 00 13 48 02 84 08 25 F5 F3 2015-02-04 08:30:08.630 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:39]- NODE 72: Sent Data successfully placed on stack. 2015-02-04 08:30:11.006 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:75]- NODE 72: SendData Request. CallBack ID = 245, Status = Transmission complete and ACK received(0) 2015-02-04 08:30:11.007 DEBUG o.o.b.z.i.protocol.ZWaveNode[:223]- NODE 72: Node has risen from the DEAD. Init stage is MANUFACTURER:{}. 2015-02-04 08:30:11.007 DEBUG o.o.b.z.i.protocol.ZWaveNode[:244]- NODE 72: Initialisation incomplete, not signalling state change. 2015-02-04 08:30:11.018 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - WAIT: Transaction complete (SendData:Request) success(true) 2015-02-04 08:30:11.018 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:30:11.022 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - MANUFACTURER: Transaction complete (SendData:Request) success(true) 2015-02-04 08:30:11.022 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 08:30:11.023 DEBUG o.o.b.z.i.p.c.ZWaveWakeUpCommandClass[:368]- NODE 72: Went to sleep 2015-02-04 08:30:11.023 DEBUG o.o.b.z.i.p.c.ZWaveWakeUpCommandClass[:423]- NODE 72: Is sleeping 2015-02-04 08:30:11.024 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1407]- NODE 72: Response processed after 2489ms/4320ms. 2015-02-04 08:30:11.092 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:864]- NODE 72: Node advancer - WAIT: The WAIT is over! 2015-02-04 08:30:11.093 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue.
cdjackson
commented
9 years ago On 4 Feb 2015, at 08:51, grzech1983 notifications@github.com wrote:
Log with "NODE 72" grep will be enough?
I'd prefer to get the full log if possible - this misses some important information. If you want to email, you can send it to chris -at- cd-jackson.com
grzech1983
commented
9 years ago Sent
cdjackson
commented
9 years ago Sorry for the slow response. The initialisation is stalled for some reason. I've been meaning to add a timer to kickstart things if this happens, so I'll try and do that today...
grzech1983
commented
9 years ago Great. When you will update I will try it and let you know if anything has changed. Another interesting thing is after updating to latest (today) binding my Aeon S2 stick appeared as Sigma Designs [ID:0, Type:0](NODE 1: No database entry: Sigma Designs [ID:0,Type:0] from log file).
cdjackson
commented
9 years ago Great. When you will update I will try it and let you know if anything has changed. Another interesting thing is after updating to latest (today) binding my Aeon S2 stick appeared as Sigma Designs ID:0, Type:0.
I'm testing the timer code now - it will be uploaded later today.
Was it your stick that was reporting incorrect manufacturer information? What it was reporting was the sigma codes (manufacturer 0, id 0, type 0). This is strange, but the information isn’t used for anything other than printing the name…
You might want to try the latest firmware from Aotec….
grzech1983
commented
9 years ago Nope. My Aeon stick was always reported as aeon stick. I was just letting you know about it. I was not sure if device ID of controller has anything to do with proper network managing.
Regarding latest firmware from Aeon I've already received some unofficial firmware from them and after updating Aeon S2 stick to this firmware network is working not so well. When returning to previous official firmware available on their website everything appears to run better. I was wondering maybe I should try to exclude and include some of my nodes again. I'll try that in next few days.
cdjackson
commented
9 years ago Nope. My Aeon stick was always reported as aeon stick. I was just letting you know about it. I was not sure if device ID of controller has anything to do with proper network managing. Ok - then I’ve seen the same thing with someone elses stick :( While I have a Aeon stick and it’s working ok, I don’t think I’d recommend them to anyone...
grzech1983
commented
9 years ago When you will update your binding I'll try to disconnect and connect stick from USB port and I'll let you know also if proper ID of Aeon device returned.
grzech1983
commented
9 years ago Yesterday I've decided to hard reset (using Domoticz with openzwave) my Aeon S2 stick and add all of my devices again.
This is result (i've updated Aeon S2 firmware to unofficial 3.8 API before adding devices again):
Devices which was not working correctly previously work fine now but there are still some issues with Aeon Multisensors. At the beggining only one of them was reporting correctly and the rest of them where not. I've stopped openhab and runned Domoticz and I've tried to update multisensors configurations and when I saw that in Domoticz appeared various reads from other multisensors I've stopped it and runned openhab again. It looks like multisensors are working fine now (except one which worked and stopped suddenly but I will monitor it today) but interesting thing is they are always greyed out in habmin. They are never green or yellow. Do you want zwave log file to check them out?
cdjackson
commented
9 years ago Yes - please provide a log during the sensor initialisation. Also, please make sure that you are running the latest binding from last night...
grzech1983
commented
9 years ago Sent. I'm running latest version (1.7.0.201502092023?)
cdjackson
commented
9 years ago As a matter of interest, what hardware are you using?
grzech1983
commented
9 years ago Ubuntu 14 Intel Atom CPU
cdjackson
commented
9 years ago Are all your devices really on mains power?
There are a few strange things in your log and it’s hard to work out where it all starts. The transmit queue is often very large - this is caused by transactions timing out, and the large network size. I see lots of transactions timing out - but in nearly all cases, the requests get responses from the device, so I don’t know why we don’t get the data returned as well. Your network is really extremely busy most of the time - the average frame period is about 0.5 seconds over the total 12 hours of the log. I suspect if I were to account for all the transaction timeouts (which lock transmissions for 15 seconds at a time) this period would drop dramatically. Also, many nodes are taking around 200ms to respond, which is generally fine, but with so much traffic, it doesn’t take much to queue things up.
I would at least consider reducing the update period on some of your meters to see if things improve - your overall retries is really low and most of the nodes are responding pretty quickly, so I think communications must be working ok. There’s just this very strange issue where some nodes aren’t responding to the requested data - only the ACK is received.
grzech1983
commented
9 years ago In current layout only one device is battery powered (smoke sensor node 65). I have also flood sensor but I forgot to include it to current network after hard resetting aeon stick.
I've changed aeon meters (multisensors and energy meter) time to some higher values.
EDIT: on the other hand any idea why multisensors are not being marked as yellow or green in openhab?
cdjackson
commented
9 years ago Let me know how it goes - I’d be happy/interested to see the log tomorrow to see if it’s any better. I still don’t understand why devices aren’t responding other than with the ACK……..
grzech1983
commented
9 years ago Hello,
I've sent you whole zwave log. I'm still struggling with configuring node 72 because it is not returning any reads. I'm also noto so confident when it comes to setting configuration for Aeon multisensors using habmin. It looks like some of values are not being saved. For some devices it looks like they are saving and for some of them not (node 72). Another thing which I've observed is that for all of my multisensors param 1 is stil as yellow value so it is still being sent for device for more than 24 hours now. This occurs for all of multisensor devices which BTW have still grey status in habmin
cdjackson
commented
9 years ago Try the latest version on the habmin site…
grzech1983
commented
9 years ago Everthing looks nice now. I still have issue with NODE 72 but I will try to exclude it and include again and see what happen then. Did you just modify zwave DB for this devices or done something more inside zwave binding?
cdjackson
commented
9 years ago I just modified the database. It seems that some of the Aeon equipment doesn't respond to some configuration requests (which seems very poor to me) - they are effectively write only. Initially I removed them from the database, but I've now added a "WriteOnly" option to allow these options to be added back into the database, but not have them requested.
grzech1983
commented
9 years ago Thanks. Everything is working fine now.
cdjackson
commented
9 years ago Brilliant - thanks for the feedback and the help improving things.
I’ll close this now :)
Hello,
do you have any suggestions how to handle situation when node is stil being initialised after few days?
When I'm trying to heal network I'm getting error:
2015-02-04 07:18:17.494 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:287]- NODE 74: Initialisation NOT yet complete. Skipping heal. 2015-02-04 07:18:17.496 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:267]- NODE 70: Starting heal 2015-02-04 07:18:17.497 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:287]- NODE 7: Initialisation NOT yet complete. Skipping heal. 2015-02-04 07:18:17.500 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:287]- NODE 72: Initialisation NOT yet complete. Skipping heal.Here is partial log with "grep "NODE 7."" to show all nodes starting with "7".
2015-02-04 05:53:29.147 DEBUG o.o.b.z.i.p.c.ZWaveNoOperationCommandClass[:72]- NODE 70: Creating new message for command No Operation 2015-02-04 05:53:29.148 DEBUG o.o.b.z.i.p.SerialMessage[:109]- NODE 70: Creating empty message of class = SendData (0x13), type = Request (0x00) 2015-02-04 05:53:29.151 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1350]- NODE 70: Sending REQUEST Message = 01 08 00 13 46 01 00 25 4F C9 2015-02-04 05:53:29.442 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:39]- NODE 70: Sent Data successfully placed on stack. 2015-02-04 05:53:29.499 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:75]- NODE 70: SendData Request. CallBack ID = 79, Status = Transmission complete and ACK received(0) 2015-02-04 05:53:29.503 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1407]- NODE 70: Response processed after 352ms/4925ms. 2015-02-04 06:36:59.321 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:341]- NODE 74: Sending periodic PING. 2015-02-04 06:36:59.322 DEBUG o.o.b.z.i.p.c.ZWaveNoOperationCommandClass[:72]- NODE 74: Creating new message for command No Operation 2015-02-04 06:36:59.324 DEBUG o.o.b.z.i.p.SerialMessage[:109]- NODE 74: Creating empty message of class = SendData (0x13), type = Request (0x00) 2015-02-04 06:36:59.328 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1350]- NODE 74: Sending REQUEST Message = 01 08 00 13 4A 01 00 25 B0 3A 2015-02-04 06:36:59.420 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:39]- NODE 74: Sent Data successfully placed on stack. 2015-02-04 06:36:59.470 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:75]- NODE 74: SendData Request. CallBack ID = 176, Status = Transmission complete and ACK received(0) 2015-02-04 06:36:59.474 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 74: Node advancer - STATIC_VALUES: Transaction complete (SendData:Request) success(true) 2015-02-04 06:36:59.474 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 74: Node advancer - checking initialisation queue. 2015-02-04 06:36:59.475 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1407]- NODE 74: Response processed after 146ms/4925ms. 2015-02-04 06:39:59.336 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:341]- NODE 72: Sending periodic PING. 2015-02-04 06:39:59.337 DEBUG o.o.b.z.i.p.c.ZWaveNoOperationCommandClass[:72]- NODE 72: Creating new message for command No Operation 2015-02-04 06:39:59.338 DEBUG o.o.b.z.i.p.SerialMessage[:109]- NODE 72: Creating empty message of class = SendData (0x13), type = Request (0x00) 2015-02-04 06:39:59.340 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1350]- NODE 72: Sending REQUEST Message = 01 08 00 13 48 01 00 25 B7 3F 2015-02-04 06:39:59.372 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:39]- NODE 72: Sent Data successfully placed on stack. 2015-02-04 06:39:59.405 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:75]- NODE 72: SendData Request. CallBack ID = 183, Status = Transmission complete and ACK received(0) 2015-02-04 06:39:59.410 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 72: Node advancer - STATIC_VALUES: Transaction complete (SendData:Request) success(true) 2015-02-04 06:39:59.410 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 72: Node advancer - checking initialisation queue. 2015-02-04 06:39:59.411 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1407]- NODE 72: Response processed after 69ms/4925ms. 2015-02-04 06:42:59.351 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:341]- NODE 7: Sending periodic PING. 2015-02-04 06:42:59.351 DEBUG o.o.b.z.i.p.c.ZWaveNoOperationCommandClass[:72]- NODE 7: Creating new message for command No Operation 2015-02-04 06:42:59.352 DEBUG o.o.b.z.i.p.SerialMessage[:109]- NODE 7: Creating empty message of class = SendData (0x13), type = Request (0x00) 2015-02-04 06:42:59.355 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1350]- NODE 7: Sending REQUEST Message = 01 08 00 13 07 01 00 25 BF 78 2015-02-04 06:42:59.387 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:39]- NODE 7: Sent Data successfully placed on stack. 2015-02-04 06:42:59.421 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:75]- NODE 7: SendData Request. CallBack ID = 191, Status = Transmission complete and ACK received(0) 2015-02-04 06:42:59.425 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:878]- NODE 7: Node advancer - DYNAMIC_VALUES: Transaction complete (SendData:Request) success(true) 2015-02-04 06:42:59.426 DEBUG o.o.b.z.i.p.i.ZWaveNodeStageAdvancer[:187]- NODE 7: Node advancer - checking initialisation queue. 2015-02-04 06:42:59.426 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1407]- NODE 7: Response processed after 70ms/4925ms. 2015-02-04 06:47:29.366 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:341]- NODE 70: Sending periodic PING. 2015-02-04 06:47:29.366 DEBUG o.o.b.z.i.p.c.ZWaveNoOperationCommandClass[:72]- NODE 70: Creating new message for command No Operation 2015-02-04 06:47:29.367 DEBUG o.o.b.z.i.p.SerialMessage[:109]- NODE 70: Creating empty message of class = SendData (0x13), type = Request (0x00) 2015-02-04 06:47:29.369 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1350]- NODE 70: Sending REQUEST Message = 01 08 00 13 46 01 00 25 CA 4C 2015-02-04 06:47:29.401 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:39]- NODE 70: Sent Data successfully placed on stack. 2015-02-04 06:47:29.442 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:75]- NODE 70: SendData Request. CallBack ID = 202, Status = Transmission complete and ACK received(0) 2015-02-04 06:47:29.446 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1407]- NODE 70: Response processed after 76ms/4925ms. 2015-02-04 07:18:17.494 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:287]- NODE 74: Initialisation NOT yet complete. Skipping heal. 2015-02-04 07:18:17.496 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:267]- NODE 70: Starting heal 2015-02-04 07:18:17.497 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:287]- NODE 7: Initialisation NOT yet complete. Skipping heal. 2015-02-04 07:18:17.500 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:287]- NODE 72: Initialisation NOT yet complete. Skipping heal. 2015-02-04 07:18:59.516 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:469]- NODE 70: NETWORK HEAL - STARTING 2015-02-04 07:18:59.517 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:478]- NODE 70: NETWORK HEAL - PING 2015-02-04 07:18:59.518 DEBUG o.o.b.z.i.p.c.ZWaveNoOperationCommandClass[:72]- NODE 70: Creating new message for command No Operation 2015-02-04 07:18:59.518 DEBUG o.o.b.z.i.p.SerialMessage[:109]- NODE 70: Creating empty message of class = SendData (0x13), type = Request (0x00) 2015-02-04 07:18:59.523 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1350]- NODE 70: Sending REQUEST Message = 01 08 00 13 46 01 00 25 14 92 2015-02-04 07:18:59.853 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:39]- NODE 70: Sent Data successfully placed on stack. 2015-02-04 07:18:59.910 DEBUG o.o.b.z.i.p.s.SendDataMessageClass[:75]- NODE 70: SendData Request. CallBack ID = 20, Status = Transmission complete and ACK received(0) 2015-02-04 07:18:59.914 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:494]- NODE 70: NETWORK HEAL - SETSUCROUTE 2015-02-04 07:18:59.914 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:499]- NODE 70: Heal is setting SUC route. 2015-02-04 07:18:59.915 DEBUG o.o.b.z.i.p.s.AssignSucReturnRouteMessageClass[:29]- NODE 70: Assigning SUC return route 2015-02-04 07:18:59.918 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveSendThread[:1407]- NODE 70: Response processed after 394ms/4925ms. 2015-02-04 07:19:01.262 DEBUG o.o.b.z.i.p.s.AssignSucReturnRouteMessageClass[:46]- NODE 70: Got AssignSucReturnRoute response. 2015-02-04 07:19:01.263 DEBUG o.o.b.z.i.p.s.AssignSucReturnRouteMessageClass[:49]- NODE 70: AssignSucReturnRoute operation started. 2015-02-04 07:20:34.523 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:494]- NODE 70: NETWORK HEAL - SETSUCROUTE 2015-02-04 07:20:34.523 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:499]- NODE 70: Heal is setting SUC route. 2015-02-04 07:20:34.524 DEBUG o.o.b.z.i.p.s.AssignSucReturnRouteMessageClass[:29]- NODE 70: Assigning SUC return route 2015-02-04 07:20:35.754 DEBUG o.o.b.z.i.p.s.AssignSucReturnRouteMessageClass[:46]- NODE 70: Got AssignSucReturnRoute response. 2015-02-04 07:20:35.755 DEBUG o.o.b.z.i.p.s.AssignSucReturnRouteMessageClass[:49]- NODE 70: AssignSucReturnRoute operation started. 2015-02-04 07:20:40.143 DEBUG o.o.b.z.i.p.s.AssignSucReturnRouteMessageClass[:64]- NODE 70: Got AssignSucReturnRoute request. 2015-02-04 07:20:40.144 DEBUG o.o.b.z.i.ZWaveNetworkMonitor[:509]- NODE 70: NETWORK HEAL - UPDATENEIGHBORS 2015-02-04 07:20:40.144 DEBUG o.o.b.z.i.p.s.RequestNodeNeighborUpdateMessageClass[:33]- NODE 70: Request neighbor update 2015-02-04 07:20:40.376 DEBUG o.o.b.z.i.p.s.RequestNodeNeighborUpdateMessageClass[:47]- NODE 70: Got NodeNeighborUpdate request. 2015-02-04 07:20:40.376 DEBUG o.o.b.z.i.p.s.RequestNodeNeighborUpdateMessageClass[:50]- NODE 70: NodeNeighborUpdate STARTEDAnother thing is that Aeon 4in1 meters never get "green" status even if they are operational and reporting various values:
Example:
2015-02-04 07:24:32.800 DEBUG o.o.b.z.i.p.ZWaveController$ZWaveReceiveThread[:1552]- Receive Message = 01 0C 00 04 08 38 06 31 05 05 01 27 00 D6 2015-02-04 07:24:32.803 DEBUG o.o.b.z.i.p.SerialMessage[:233]- Assembled message buffer = 01 0C 00 04 08 38 06 31 05 05 01 27 00 D6 2015-02-04 07:24:32.804 DEBUG o.o.b.z.i.p.ZWaveController[:1246]- Process Message = 01 0C 00 04 08 38 06 31 05 05 01 27 00 D6 2015-02-04 07:24:32.804 DEBUG o.o.b.z.i.p.ZWaveController[:174]- Message: class = ApplicationCommandHandler (0x04), type = Request (0x00), payload = 08 38 06 31 05 05 01 27 00 2015-02-04 07:24:32.805 DEBUG o.o.b.z.i.p.s.ApplicationCommandMessageClass[:38]- NODE 56: Application Command Request (ALIVE:STATIC_VALUES) 2015-02-04 07:24:32.806 DEBUG o.o.b.z.i.p.s.ApplicationCommandMessageClass[:57]- NODE 56: Incoming command class SENSOR_MULTILEVEL (0x31) 2015-02-04 07:24:32.806 DEBUG o.o.b.z.i.p.c.ZWaveMultiLevelSensorCommandClass[:97]- NODE 56: Received Sensor Multi Level Request 2015-02-04 07:24:32.807 DEBUG o.o.b.z.i.p.c.ZWaveMultiLevelSensorCommandClass[:131]- NODE 56: Sensor Multi Level REPORT received 2015-02-04 07:24:32.807 DEBUG o.o.b.z.i.p.c.ZWaveMultiLevelSensorCommandClass[:141]- NODE 56: Sensor Type = RelativeHumidity(5), Scale = 0 2015-02-04 07:24:32.808 DEBUG o.o.b.z.i.p.c.ZWaveMultiLevelSensorCommandClass[:150]- NODE 56: Sensor Value = 39 2015-02-04 07:24:32.809 DEBUG o.o.b.z.i.p.ZWaveController[:656]- Notifying event listeners 2015-02-04 07:24:32.809 DEBUG o.o.b.z.i.ZWaveActiveBinding[:430]- ZwaveIncomingEvent 2015-02-04 07:24:32.810 DEBUG o.o.b.z.i.ZWaveActiveBinding[:447]- NODE 56: Got a value event from Z-Wave network, endpoint = 0, command class = SENSOR_MULTILEVEL, value = 39 2015-02-04 07:24:32.813 DEBUG o.o.b.z.i.p.s.ApplicationCommandMessageClass[:86]- Transaction not completed: node address inconsistent.do you have any ideas?
Node 69 is Aeon energy meter v1 it has recently "lost" his name but it works and reports usage.
Regards