search

cdjackson / HABmin

A web admin console for openHAB home automation
http://www.cd-jackson.com/index.php/openhab/habmin
217 stars 51 forks source link

[zwave] node heal attempted after every command sent #218

Open petrklus opened 9 years ago

petrklus commented 9 years ago

Hello,

I've noticed that switching dual-relay equipped lights can take surprisingly long amount of time. When looking at logs, I've noticed that every time I toggle a light (ON and then OFF), the binding is attempting a heal. I've switched the light ON, waited 1s and then switched it off. The ON command seems to go through, then after the OFF is issued the binding is attempting a heal. This happens every time and causes delay in command propagation

Please see below excerpt of the logs.

2015-02-08 20:08:07.304 [TRACE] [veController$WatchDogTimerTask:1392]- Watchdog: Checking Serial threads
2015-02-08 20:08:17.304 [TRACE] [veController$WatchDogTimerTask:1392]- Watchdog: Checking Serial threads
2015-02-08 20:08:27.305 [TRACE] [veController$WatchDogTimerTask:1392]- Watchdog: Checking Serial threads
2015-02-08 20:08:37.304 [TRACE] [veController$WatchDogTimerTask:1392]- Watchdog: Checking Serial threads
2015-02-08 20:08:44.803 [TRACE] [.z.internal.ZWaveActiveBinding:222 ]- internalReceiveCommand(itemname = ZWave_Light_IND_Kitchen, Command = ON)
2015-02-08 20:08:44.804 [DEBUG] [.ZWaveBinarySwitchCommandClass:145 ]- NODE 2: Creating new message for application command SWITCH_BINARY_SET
2015-02-08 20:08:44.804 [DEBUG] [o.b.z.i.protocol.SerialMessage:108 ]- NODE 2: Creating empty message of class = SendData (0x13), type = Request (0x00)
2015-02-08 20:08:44.805 [DEBUG] [.z.internal.protocol.ZWaveNode:567 ]- NODE 2: Encapsulating message, instance / endpoint 1
2015-02-08 20:08:44.806 [DEBUG] [ZWaveMultiInstanceCommandClass:516 ]- NODE 2: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2015-02-08 20:08:44.807 [DEBUG] [b.z.i.protocol.ZWaveController:866 ]- Callback ID = 219
2015-02-08 20:08:44.808 [DEBUG] [b.z.i.protocol.ZWaveController:493 ]- Enqueueing message. Queue length = 1
2015-02-08 20:08:44.808 [DEBUG] [WaveController$ZWaveSendThread:1091]- Took message from queue for sending. Queue length = 0
2015-02-08 20:08:44.809 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0xAF
2015-02-08 20:08:44.810 [DEBUG] [o.b.z.i.protocol.SerialMessage:232 ]- Assembled message buffer = 01 0E 00 13 02 07 60 0D 01 01 25 01 FF 25 DB AF 
2015-02-08 20:08:44.810 [DEBUG] [WaveController$ZWaveSendThread:1136]- NODE 2: Sending REQUEST Message = 01 0E 00 13 02 07 60 0D 01 01 25 01 FF 25 DB AF 
2015-02-08 20:08:44.813 [TRACE] [eController$ZWaveReceiveThread:1332]- Received ACK
2015-02-08 20:08:44.838 [TRACE] [eController$ZWaveReceiveThread:1326]- Reading message finished
2015-02-08 20:08:44.838 [DEBUG] [eController$ZWaveReceiveThread:1327]- Receive Message = 01 04 01 13 01 E8 
2015-02-08 20:08:44.838 [TRACE] [o.b.z.i.protocol.SerialMessage:135 ]- NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8 
2015-02-08 20:08:44.839 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0xE8
2015-02-08 20:08:44.839 [TRACE] [o.b.z.i.protocol.SerialMessage:139 ]- NODE 255: Message checksum calculated = 0xE8, received = 0xE8
2015-02-08 20:08:44.839 [TRACE] [o.b.z.i.protocol.SerialMessage:141 ]- NODE 255: Checksum matched
2015-02-08 20:08:44.839 [TRACE] [o.b.z.i.protocol.SerialMessage:152 ]- NODE 255: Message payload = 01 
2015-02-08 20:08:44.840 [TRACE] [eController$ZWaveReceiveThread:1246]- Message is valid, sending ACK
2015-02-08 20:08:44.840 [TRACE] [b.z.i.protocol.ZWaveController:170 ]- Incoming message to process
2015-02-08 20:08:44.840 [DEBUG] [b.z.i.protocol.ZWaveController:171 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
2015-02-08 20:08:44.841 [TRACE] [b.z.i.protocol.ZWaveController:225 ]- Incoming Message type = RESPONSE
2015-02-08 20:08:44.841 [TRACE] [b.z.i.p.s.SendDataMessageClass:33  ]- Handle Message Send Data Response
2015-02-08 20:08:44.841 [DEBUG] [b.z.i.p.s.SendDataMessageClass:35  ]- NODE 2: Sent Data successfully placed on stack.
2015-02-08 20:08:45.279 [TRACE] [eController$ZWaveReceiveThread:1326]- Reading message finished
2015-02-08 20:08:45.280 [DEBUG] [eController$ZWaveReceiveThread:1327]- Receive Message = 01 05 00 13 DB 01 33 
2015-02-08 20:08:45.280 [TRACE] [o.b.z.i.protocol.SerialMessage:135 ]- NODE 255: Creating new SerialMessage from buffer = 01 05 00 13 DB 01 33 
2015-02-08 20:08:45.280 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0x33
2015-02-08 20:08:45.281 [TRACE] [o.b.z.i.protocol.SerialMessage:139 ]- NODE 255: Message checksum calculated = 0x33, received = 0x33
2015-02-08 20:08:45.281 [TRACE] [o.b.z.i.protocol.SerialMessage:141 ]- NODE 255: Checksum matched
2015-02-08 20:08:45.281 [TRACE] [o.b.z.i.protocol.SerialMessage:152 ]- NODE 255: Message payload = DB 01 
2015-02-08 20:08:45.282 [TRACE] [eController$ZWaveReceiveThread:1246]- Message is valid, sending ACK
2015-02-08 20:08:45.282 [TRACE] [b.z.i.protocol.ZWaveController:170 ]- Incoming message to process
2015-02-08 20:08:45.282 [DEBUG] [b.z.i.protocol.ZWaveController:171 ]- Message: class = SendData (0x13), type = Request (0x00), payload = DB 01 
2015-02-08 20:08:45.283 [TRACE] [b.z.i.protocol.ZWaveController:191 ]- Incoming Message type = REQUEST
2015-02-08 20:08:45.283 [TRACE] [b.z.i.p.s.SendDataMessageClass:55  ]- Handle Message Send Data Request
2015-02-08 20:08:45.283 [DEBUG] [b.z.i.p.s.SendDataMessageClass:72  ]- NODE 2: SendData Request. CallBack ID = 219, Status = Transmission complete, no ACK received(1)
2015-02-08 20:08:45.284 [TRACE] [b.z.i.p.s.SendDataMessageClass:116 ]- NODE 2: Handling failed message.
2015-02-08 20:08:45.284 [ERROR] [b.z.i.p.s.SendDataMessageClass:124 ]- NODE 2: Node is DEAD. Dropping message.
2015-02-08 20:08:45.284 [DEBUG] [b.z.i.protocol.ZWaveController:508 ]- Notifying event listeners
2015-02-08 20:08:45.284 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveActiveBinding@c49f1
2015-02-08 20:08:45.285 [DEBUG] [.z.internal.ZWaveActiveBinding:431 ]- ZwaveIncomingEvent
2015-02-08 20:08:45.285 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveNetworkMonitor@15a61ee
2015-02-08 20:08:45.285 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.config.ZWaveConfiguration@8a17b0
2015-02-08 20:08:45.286 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@15885a7
2015-02-08 20:08:45.286 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16b96f7
2015-02-08 20:08:45.286 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@48531b
2015-02-08 20:08:45.286 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16629df
2015-02-08 20:08:45.287 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@17fb691
2015-02-08 20:08:45.287 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@136f0df
2015-02-08 20:08:45.287 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@f136f2
2015-02-08 20:08:45.287 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@14b396f
2015-02-08 20:08:45.287 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@82d26f
2015-02-08 20:08:45.288 [TRACE] [b.z.i.protocol.ZWaveController:200 ]- Released. Transaction completed permit count -> 1
2015-02-08 20:08:45.288 [DEBUG] [WaveController$ZWaveSendThread:1193]- Response processed after 477ms/2675ms.
2015-02-08 20:08:45.288 [TRACE] [WaveController$ZWaveSendThread:1194]- Acquired. Transaction completed permit count -> 0
2015-02-08 20:08:47.305 [TRACE] [veController$WatchDogTimerTask:1392]- Watchdog: Checking Serial threads
2015-02-08 20:08:48.175 [TRACE] [.z.internal.ZWaveActiveBinding:222 ]- internalReceiveCommand(itemname = ZWave_Light_IND_Kitchen, Command = OFF)
2015-02-08 20:08:48.175 [DEBUG] [.ZWaveBinarySwitchCommandClass:145 ]- NODE 2: Creating new message for application command SWITCH_BINARY_SET
2015-02-08 20:08:48.176 [DEBUG] [o.b.z.i.protocol.SerialMessage:108 ]- NODE 2: Creating empty message of class = SendData (0x13), type = Request (0x00)
2015-02-08 20:08:48.177 [DEBUG] [.z.internal.protocol.ZWaveNode:567 ]- NODE 2: Encapsulating message, instance / endpoint 1
2015-02-08 20:08:48.177 [DEBUG] [ZWaveMultiInstanceCommandClass:516 ]- NODE 2: Creating new message for command MULTI_CHANNEL_ENCAP endpoint 1
2015-02-08 20:08:48.178 [DEBUG] [b.z.i.protocol.ZWaveController:866 ]- Callback ID = 220
2015-02-08 20:08:48.179 [DEBUG] [b.z.i.protocol.ZWaveController:493 ]- Enqueueing message. Queue length = 1
2015-02-08 20:08:48.179 [DEBUG] [WaveController$ZWaveSendThread:1091]- Took message from queue for sending. Queue length = 0
2015-02-08 20:08:48.180 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0x57
2015-02-08 20:08:48.181 [DEBUG] [o.b.z.i.protocol.SerialMessage:232 ]- Assembled message buffer = 01 0E 00 13 02 07 60 0D 01 01 25 01 00 25 DC 57 
2015-02-08 20:08:48.181 [DEBUG] [WaveController$ZWaveSendThread:1136]- NODE 2: Sending REQUEST Message = 01 0E 00 13 02 07 60 0D 01 01 25 01 00 25 DC 57 
2015-02-08 20:08:48.184 [TRACE] [eController$ZWaveReceiveThread:1332]- Received ACK
2015-02-08 20:08:48.208 [TRACE] [eController$ZWaveReceiveThread:1326]- Reading message finished
2015-02-08 20:08:48.209 [DEBUG] [eController$ZWaveReceiveThread:1327]- Receive Message = 01 04 01 13 01 E8 
2015-02-08 20:08:48.209 [TRACE] [o.b.z.i.protocol.SerialMessage:135 ]- NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8 
2015-02-08 20:08:48.210 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0xE8
2015-02-08 20:08:48.210 [TRACE] [o.b.z.i.protocol.SerialMessage:139 ]- NODE 255: Message checksum calculated = 0xE8, received = 0xE8
2015-02-08 20:08:48.210 [TRACE] [o.b.z.i.protocol.SerialMessage:141 ]- NODE 255: Checksum matched
2015-02-08 20:08:48.210 [TRACE] [o.b.z.i.protocol.SerialMessage:152 ]- NODE 255: Message payload = 01 
2015-02-08 20:08:48.211 [TRACE] [eController$ZWaveReceiveThread:1246]- Message is valid, sending ACK
2015-02-08 20:08:48.211 [TRACE] [b.z.i.protocol.ZWaveController:170 ]- Incoming message to process
2015-02-08 20:08:48.211 [DEBUG] [b.z.i.protocol.ZWaveController:171 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
2015-02-08 20:08:48.212 [TRACE] [b.z.i.protocol.ZWaveController:225 ]- Incoming Message type = RESPONSE
2015-02-08 20:08:48.212 [TRACE] [b.z.i.p.s.SendDataMessageClass:33  ]- Handle Message Send Data Response
2015-02-08 20:08:48.212 [DEBUG] [b.z.i.p.s.SendDataMessageClass:35  ]- NODE 2: Sent Data successfully placed on stack.
2015-02-08 20:08:48.770 [TRACE] [eController$ZWaveReceiveThread:1326]- Reading message finished
2015-02-08 20:08:48.770 [DEBUG] [eController$ZWaveReceiveThread:1327]- Receive Message = 01 05 00 13 DC 01 34 
2015-02-08 20:08:48.770 [TRACE] [o.b.z.i.protocol.SerialMessage:135 ]- NODE 255: Creating new SerialMessage from buffer = 01 05 00 13 DC 01 34 
2015-02-08 20:08:48.771 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0x34
2015-02-08 20:08:48.771 [TRACE] [o.b.z.i.protocol.SerialMessage:139 ]- NODE 255: Message checksum calculated = 0x34, received = 0x34
2015-02-08 20:08:48.771 [TRACE] [o.b.z.i.protocol.SerialMessage:141 ]- NODE 255: Checksum matched
2015-02-08 20:08:48.771 [TRACE] [o.b.z.i.protocol.SerialMessage:152 ]- NODE 255: Message payload = DC 01 
2015-02-08 20:08:48.772 [TRACE] [eController$ZWaveReceiveThread:1246]- Message is valid, sending ACK
2015-02-08 20:08:48.772 [TRACE] [b.z.i.protocol.ZWaveController:170 ]- Incoming message to process
2015-02-08 20:08:48.772 [DEBUG] [b.z.i.protocol.ZWaveController:171 ]- Message: class = SendData (0x13), type = Request (0x00), payload = DC 01 
2015-02-08 20:08:48.773 [TRACE] [b.z.i.protocol.ZWaveController:191 ]- Incoming Message type = REQUEST
2015-02-08 20:08:48.773 [TRACE] [b.z.i.p.s.SendDataMessageClass:55  ]- Handle Message Send Data Request
2015-02-08 20:08:48.773 [DEBUG] [b.z.i.p.s.SendDataMessageClass:72  ]- NODE 2: SendData Request. CallBack ID = 220, Status = Transmission complete, no ACK received(1)
2015-02-08 20:08:48.773 [TRACE] [b.z.i.p.s.SendDataMessageClass:116 ]- NODE 2: Handling failed message.
2015-02-08 20:08:48.774 [DEBUG] [.z.internal.protocol.ZWaveNode:406 ]- NODE 2: Retry count exceeded. Node is DEAD.
2015-02-08 20:08:48.774 [DEBUG] [b.z.i.protocol.ZWaveController:508 ]- Notifying event listeners
2015-02-08 20:08:48.774 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveActiveBinding@c49f1
2015-02-08 20:08:48.775 [DEBUG] [.z.internal.ZWaveActiveBinding:431 ]- ZwaveIncomingEvent
2015-02-08 20:08:48.775 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveNetworkMonitor@15a61ee
2015-02-08 20:08:48.775 [DEBUG] [z.internal.ZWaveNetworkMonitor:667 ]- NODE 2: Node Status event - Node is Dead
2015-02-08 20:08:48.775 [DEBUG] [i.p.s.IsFailedNodeMessageClass:30  ]- NODE 2: Requesting IsFailedNode status from controller.
2015-02-08 20:08:48.776 [DEBUG] [o.b.z.i.protocol.SerialMessage:108 ]- NODE 255: Creating empty message of class = IsFailedNodeID (0x62), type = Request (0x00)
2015-02-08 20:08:48.776 [DEBUG] [b.z.i.protocol.ZWaveController:493 ]- Enqueueing message. Queue length = 1
2015-02-08 20:08:48.776 [DEBUG] [z.internal.ZWaveNetworkMonitor:686 ]- NODE 2: Dead node - requesting network heal.
2015-02-08 20:08:48.777 [DEBUG] [z.internal.ZWaveNetworkMonitor:261 ]- NODE 2: Starting heal
2015-02-08 20:08:48.777 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.config.ZWaveConfiguration@8a17b0
2015-02-08 20:08:48.777 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@15885a7
2015-02-08 20:08:48.778 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16b96f7
2015-02-08 20:08:48.778 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@48531b
2015-02-08 20:08:48.778 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16629df
2015-02-08 20:08:48.778 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@17fb691
2015-02-08 20:08:48.779 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@136f0df
2015-02-08 20:08:48.779 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@f136f2
2015-02-08 20:08:48.779 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@14b396f
2015-02-08 20:08:48.779 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@82d26f
2015-02-08 20:08:48.779 [ERROR] [b.z.i.p.s.SendDataMessageClass:124 ]- NODE 2: Node is DEAD. Dropping message.
2015-02-08 20:08:48.780 [DEBUG] [b.z.i.protocol.ZWaveController:508 ]- Notifying event listeners
2015-02-08 20:08:48.780 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveActiveBinding@c49f1
2015-02-08 20:08:48.780 [DEBUG] [.z.internal.ZWaveActiveBinding:431 ]- ZwaveIncomingEvent
2015-02-08 20:08:48.780 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveNetworkMonitor@15a61ee
2015-02-08 20:08:48.781 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.config.ZWaveConfiguration@8a17b0
2015-02-08 20:08:48.781 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@15885a7
2015-02-08 20:08:48.781 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16b96f7
2015-02-08 20:08:48.781 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@48531b
2015-02-08 20:08:48.781 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16629df
2015-02-08 20:08:48.782 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@17fb691
2015-02-08 20:08:48.782 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@136f0df
2015-02-08 20:08:48.782 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@f136f2
2015-02-08 20:08:48.782 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@14b396f
2015-02-08 20:08:48.783 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@82d26f
2015-02-08 20:08:48.783 [TRACE] [b.z.i.protocol.ZWaveController:200 ]- Released. Transaction completed permit count -> 1
2015-02-08 20:08:48.783 [DEBUG] [WaveController$ZWaveSendThread:1193]- Response processed after 602ms/2675ms.
2015-02-08 20:08:48.783 [TRACE] [WaveController$ZWaveSendThread:1194]- Acquired. Transaction completed permit count -> 0
2015-02-08 20:08:48.784 [DEBUG] [WaveController$ZWaveSendThread:1091]- Took message from queue for sending. Queue length = 0
2015-02-08 20:08:48.784 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0x9B
2015-02-08 20:08:48.784 [DEBUG] [o.b.z.i.protocol.SerialMessage:232 ]- Assembled message buffer = 01 04 00 62 02 9B 
2015-02-08 20:08:48.785 [DEBUG] [WaveController$ZWaveSendThread:1136]- NODE 255: Sending REQUEST Message = 01 04 00 62 02 9B 
2015-02-08 20:08:48.786 [TRACE] [eController$ZWaveReceiveThread:1332]- Received ACK
2015-02-08 20:08:48.787 [TRACE] [eController$ZWaveReceiveThread:1326]- Reading message finished
2015-02-08 20:08:48.787 [DEBUG] [eController$ZWaveReceiveThread:1327]- Receive Message = 01 04 01 62 01 99 
2015-02-08 20:08:48.787 [TRACE] [o.b.z.i.protocol.SerialMessage:135 ]- NODE 255: Creating new SerialMessage from buffer = 01 04 01 62 01 99 
2015-02-08 20:08:48.788 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0x99
2015-02-08 20:08:48.788 [TRACE] [o.b.z.i.protocol.SerialMessage:139 ]- NODE 255: Message checksum calculated = 0x99, received = 0x99
2015-02-08 20:08:48.788 [TRACE] [o.b.z.i.protocol.SerialMessage:141 ]- NODE 255: Checksum matched
2015-02-08 20:08:48.788 [TRACE] [o.b.z.i.protocol.SerialMessage:152 ]- NODE 255: Message payload = 01 
2015-02-08 20:08:48.789 [TRACE] [eController$ZWaveReceiveThread:1246]- Message is valid, sending ACK
2015-02-08 20:08:48.789 [TRACE] [b.z.i.protocol.ZWaveController:170 ]- Incoming message to process
2015-02-08 20:08:48.789 [DEBUG] [b.z.i.protocol.ZWaveController:171 ]- Message: class = IsFailedNodeID (0x62), type = Response (0x01), payload = 01 
2015-02-08 20:08:48.790 [TRACE] [b.z.i.protocol.ZWaveController:225 ]- Incoming Message type = RESPONSE
2015-02-08 20:08:48.790 [TRACE] [i.p.s.IsFailedNodeMessageClass:41  ]- Handle IsFailedNode Response
2015-02-08 20:08:48.790 [DEBUG] [b.z.i.protocol.ZWaveController:508 ]- Notifying event listeners
2015-02-08 20:08:48.790 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveActiveBinding@c49f1
2015-02-08 20:08:48.791 [DEBUG] [.z.internal.ZWaveActiveBinding:431 ]- ZwaveIncomingEvent
2015-02-08 20:08:48.791 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveNetworkMonitor@15a61ee
2015-02-08 20:08:48.791 [DEBUG] [z.internal.ZWaveNetworkMonitor:587 ]- NODE 2: Network heal EVENT
2015-02-08 20:08:48.792 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.config.ZWaveConfiguration@8a17b0
2015-02-08 20:08:48.792 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@15885a7
2015-02-08 20:08:48.792 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16b96f7
2015-02-08 20:08:48.792 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@48531b
2015-02-08 20:08:48.793 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16629df
2015-02-08 20:08:48.793 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@17fb691
2015-02-08 20:08:48.793 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@136f0df
2015-02-08 20:08:48.793 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@f136f2
2015-02-08 20:08:48.794 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@14b396f
2015-02-08 20:08:48.794 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@82d26f
2015-02-08 20:08:48.794 [WARN ] [b.z.i.protocol.ZWaveController:559 ]- NODE 2: Marking node as FAILED because its on the controllers failed node list.
2015-02-08 20:08:48.794 [DEBUG] [b.z.i.protocol.ZWaveController:508 ]- Notifying event listeners
2015-02-08 20:08:48.795 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveActiveBinding@c49f1
2015-02-08 20:08:48.795 [DEBUG] [.z.internal.ZWaveActiveBinding:431 ]- ZwaveIncomingEvent
2015-02-08 20:08:48.795 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveNetworkMonitor@15a61ee
2015-02-08 20:08:48.795 [DEBUG] [z.internal.ZWaveNetworkMonitor:667 ]- NODE 2: Node Status event - Node is Failed
2015-02-08 20:08:48.796 [DEBUG] [z.internal.ZWaveNetworkMonitor:686 ]- NODE 2: Failed node - requesting network heal.
2015-02-08 20:08:48.796 [DEBUG] [z.internal.ZWaveNetworkMonitor:261 ]- NODE 2: Starting heal
2015-02-08 20:08:48.796 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.config.ZWaveConfiguration@8a17b0
2015-02-08 20:08:48.796 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@15885a7
2015-02-08 20:08:48.797 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16b96f7
2015-02-08 20:08:48.797 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@48531b
2015-02-08 20:08:48.797 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16629df
2015-02-08 20:08:48.798 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@17fb691
2015-02-08 20:08:48.798 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@136f0df
2015-02-08 20:08:48.798 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@f136f2
2015-02-08 20:08:48.798 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@14b396f
2015-02-08 20:08:48.799 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@82d26f
2015-02-08 20:08:48.799 [WARN ] [i.p.s.IsFailedNodeMessageClass:45  ]- NODE 2: Is currently marked as failed by the controller!
2015-02-08 20:08:48.799 [DEBUG] [b.z.i.protocol.ZWaveController:508 ]- Notifying event listeners
2015-02-08 20:08:48.799 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveActiveBinding@c49f1
2015-02-08 20:08:48.799 [DEBUG] [.z.internal.ZWaveActiveBinding:431 ]- ZwaveIncomingEvent
2015-02-08 20:08:48.800 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveNetworkMonitor@15a61ee
2015-02-08 20:08:48.800 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.config.ZWaveConfiguration@8a17b0
2015-02-08 20:08:48.800 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@15885a7
2015-02-08 20:08:48.800 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16b96f7
2015-02-08 20:08:48.801 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@48531b
2015-02-08 20:08:48.801 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16629df
2015-02-08 20:08:48.801 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@17fb691
2015-02-08 20:08:48.801 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@136f0df
2015-02-08 20:08:48.801 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@f136f2
2015-02-08 20:08:48.802 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@14b396f
2015-02-08 20:08:48.802 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@82d26f
2015-02-08 20:08:48.802 [TRACE] [b.z.i.protocol.ZWaveController:234 ]- Released. Transaction completed permit count -> 1
2015-02-08 20:08:48.802 [DEBUG] [WaveController$ZWaveSendThread:1193]- Response processed after 17ms/2675ms.
2015-02-08 20:08:48.802 [TRACE] [WaveController$ZWaveSendThread:1194]- Acquired. Transaction completed permit count -> 0
2015-02-08 20:08:53.077 [DEBUG] [z.internal.ZWaveNetworkMonitor:450 ]- NODE 2: NETWORK HEAL - STARTING
2015-02-08 20:08:53.078 [DEBUG] [c.ZWaveNoOperationCommandClass:72  ]- NODE 2: Creating new message for command No Operation
2015-02-08 20:08:53.078 [DEBUG] [o.b.z.i.protocol.SerialMessage:108 ]- NODE 2: Creating empty message of class = SendData (0x13), type = Request (0x00)
2015-02-08 20:08:53.078 [DEBUG] [b.z.i.protocol.ZWaveController:866 ]- Callback ID = 221
2015-02-08 20:08:53.079 [DEBUG] [b.z.i.protocol.ZWaveController:493 ]- Enqueueing message. Queue length = 1
2015-02-08 20:08:53.079 [DEBUG] [WaveController$ZWaveSendThread:1091]- Took message from queue for sending. Queue length = 0
2015-02-08 20:08:53.079 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0x1F
2015-02-08 20:08:53.080 [DEBUG] [o.b.z.i.protocol.SerialMessage:232 ]- Assembled message buffer = 01 08 00 13 02 01 00 25 DD 1F 
2015-02-08 20:08:53.080 [DEBUG] [WaveController$ZWaveSendThread:1136]- NODE 2: Sending REQUEST Message = 01 08 00 13 02 01 00 25 DD 1F 
2015-02-08 20:08:53.083 [TRACE] [eController$ZWaveReceiveThread:1332]- Received ACK
2015-02-08 20:08:53.107 [TRACE] [eController$ZWaveReceiveThread:1326]- Reading message finished
2015-02-08 20:08:53.107 [DEBUG] [eController$ZWaveReceiveThread:1327]- Receive Message = 01 04 01 13 01 E8 
2015-02-08 20:08:53.107 [TRACE] [o.b.z.i.protocol.SerialMessage:135 ]- NODE 255: Creating new SerialMessage from buffer = 01 04 01 13 01 E8 
2015-02-08 20:08:53.108 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0xE8
2015-02-08 20:08:53.108 [TRACE] [o.b.z.i.protocol.SerialMessage:139 ]- NODE 255: Message checksum calculated = 0xE8, received = 0xE8
2015-02-08 20:08:53.108 [TRACE] [o.b.z.i.protocol.SerialMessage:141 ]- NODE 255: Checksum matched
2015-02-08 20:08:53.109 [TRACE] [o.b.z.i.protocol.SerialMessage:152 ]- NODE 255: Message payload = 01 
2015-02-08 20:08:53.109 [TRACE] [eController$ZWaveReceiveThread:1246]- Message is valid, sending ACK
2015-02-08 20:08:53.109 [TRACE] [b.z.i.protocol.ZWaveController:170 ]- Incoming message to process
2015-02-08 20:08:53.109 [DEBUG] [b.z.i.protocol.ZWaveController:171 ]- Message: class = SendData (0x13), type = Response (0x01), payload = 01 
2015-02-08 20:08:53.110 [TRACE] [b.z.i.protocol.ZWaveController:225 ]- Incoming Message type = RESPONSE
2015-02-08 20:08:53.110 [TRACE] [b.z.i.p.s.SendDataMessageClass:33  ]- Handle Message Send Data Response
2015-02-08 20:08:53.110 [DEBUG] [b.z.i.p.s.SendDataMessageClass:35  ]- NODE 2: Sent Data successfully placed on stack.
2015-02-08 20:08:53.550 [TRACE] [eController$ZWaveReceiveThread:1326]- Reading message finished
2015-02-08 20:08:53.551 [DEBUG] [eController$ZWaveReceiveThread:1327]- Receive Message = 01 05 00 13 DD 01 35 
2015-02-08 20:08:53.551 [TRACE] [o.b.z.i.protocol.SerialMessage:135 ]- NODE 255: Creating new SerialMessage from buffer = 01 05 00 13 DD 01 35 
2015-02-08 20:08:53.552 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0x35
2015-02-08 20:08:53.552 [TRACE] [o.b.z.i.protocol.SerialMessage:139 ]- NODE 255: Message checksum calculated = 0x35, received = 0x35
2015-02-08 20:08:53.553 [TRACE] [o.b.z.i.protocol.SerialMessage:141 ]- NODE 255: Checksum matched
2015-02-08 20:08:53.553 [TRACE] [o.b.z.i.protocol.SerialMessage:152 ]- NODE 255: Message payload = DD 01 
2015-02-08 20:08:53.553 [TRACE] [eController$ZWaveReceiveThread:1246]- Message is valid, sending ACK
2015-02-08 20:08:53.554 [TRACE] [b.z.i.protocol.ZWaveController:170 ]- Incoming message to process
2015-02-08 20:08:53.554 [DEBUG] [b.z.i.protocol.ZWaveController:171 ]- Message: class = SendData (0x13), type = Request (0x00), payload = DD 01 
2015-02-08 20:08:53.554 [TRACE] [b.z.i.protocol.ZWaveController:191 ]- Incoming Message type = REQUEST
2015-02-08 20:08:53.555 [TRACE] [b.z.i.p.s.SendDataMessageClass:55  ]- Handle Message Send Data Request
2015-02-08 20:08:53.555 [DEBUG] [b.z.i.p.s.SendDataMessageClass:72  ]- NODE 2: SendData Request. CallBack ID = 221, Status = Transmission complete, no ACK received(1)
2015-02-08 20:08:53.555 [TRACE] [b.z.i.p.s.SendDataMessageClass:116 ]- NODE 2: Handling failed message.
2015-02-08 20:08:53.556 [ERROR] [b.z.i.p.s.SendDataMessageClass:124 ]- NODE 2: Node is DEAD. Dropping message.
2015-02-08 20:08:53.556 [DEBUG] [b.z.i.protocol.ZWaveController:508 ]- Notifying event listeners
2015-02-08 20:08:53.556 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveActiveBinding@c49f1
2015-02-08 20:08:53.557 [DEBUG] [.z.internal.ZWaveActiveBinding:431 ]- ZwaveIncomingEvent
2015-02-08 20:08:53.557 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveNetworkMonitor@15a61ee
2015-02-08 20:08:53.557 [DEBUG] [z.internal.ZWaveNetworkMonitor:472 ]- NODE 2: Heal is setting SUC route.
2015-02-08 20:08:53.557 [DEBUG] [b.z.i.protocol.ZWaveController:866 ]- Callback ID = 222
2015-02-08 20:08:53.558 [DEBUG] [signSucReturnRouteMessageClass:29  ]- NODE 2: Assigning SUC return route
2015-02-08 20:08:53.558 [DEBUG] [o.b.z.i.protocol.SerialMessage:108 ]- NODE 255: Creating empty message of class = AssignSucReturnRoute (0x51), type = Request (0x00)
2015-02-08 20:08:53.559 [DEBUG] [b.z.i.protocol.ZWaveController:493 ]- Enqueueing message. Queue length = 1
2015-02-08 20:08:53.559 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.config.ZWaveConfiguration@8a17b0
2015-02-08 20:08:53.560 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@15885a7
2015-02-08 20:08:53.560 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16b96f7
2015-02-08 20:08:53.560 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@48531b
2015-02-08 20:08:53.561 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16629df
2015-02-08 20:08:53.561 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@17fb691
2015-02-08 20:08:53.561 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@136f0df
2015-02-08 20:08:53.562 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@f136f2
2015-02-08 20:08:53.562 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@14b396f
2015-02-08 20:08:53.562 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@82d26f
2015-02-08 20:08:53.563 [TRACE] [b.z.i.protocol.ZWaveController:200 ]- Released. Transaction completed permit count -> 1
2015-02-08 20:08:53.563 [DEBUG] [WaveController$ZWaveSendThread:1193]- Response processed after 483ms/2675ms.
2015-02-08 20:08:53.563 [TRACE] [WaveController$ZWaveSendThread:1194]- Acquired. Transaction completed permit count -> 0
2015-02-08 20:08:53.564 [DEBUG] [WaveController$ZWaveSendThread:1091]- Took message from queue for sending. Queue length = 0
2015-02-08 20:08:53.565 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0x77
2015-02-08 20:08:53.565 [DEBUG] [o.b.z.i.protocol.SerialMessage:232 ]- Assembled message buffer = 01 05 00 51 02 DE 77 
2015-02-08 20:08:53.566 [DEBUG] [WaveController$ZWaveSendThread:1136]- NODE 255: Sending REQUEST Message = 01 05 00 51 02 DE 77 
2015-02-08 20:08:53.568 [TRACE] [eController$ZWaveReceiveThread:1332]- Received ACK
2015-02-08 20:08:53.594 [TRACE] [eController$ZWaveReceiveThread:1326]- Reading message finished
2015-02-08 20:08:53.594 [DEBUG] [eController$ZWaveReceiveThread:1327]- Receive Message = 01 04 01 51 01 AA 
2015-02-08 20:08:53.595 [TRACE] [o.b.z.i.protocol.SerialMessage:135 ]- NODE 255: Creating new SerialMessage from buffer = 01 04 01 51 01 AA 
2015-02-08 20:08:53.595 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0xAA
2015-02-08 20:08:53.595 [TRACE] [o.b.z.i.protocol.SerialMessage:139 ]- NODE 255: Message checksum calculated = 0xAA, received = 0xAA
2015-02-08 20:08:53.595 [TRACE] [o.b.z.i.protocol.SerialMessage:141 ]- NODE 255: Checksum matched
2015-02-08 20:08:53.596 [TRACE] [o.b.z.i.protocol.SerialMessage:152 ]- NODE 255: Message payload = 01 
2015-02-08 20:08:53.596 [TRACE] [eController$ZWaveReceiveThread:1246]- Message is valid, sending ACK
2015-02-08 20:08:53.596 [TRACE] [b.z.i.protocol.ZWaveController:170 ]- Incoming message to process
2015-02-08 20:08:53.597 [DEBUG] [b.z.i.protocol.ZWaveController:171 ]- Message: class = AssignSucReturnRoute (0x51), type = Response (0x01), payload = 01 
2015-02-08 20:08:53.597 [TRACE] [b.z.i.protocol.ZWaveController:225 ]- Incoming Message type = RESPONSE
2015-02-08 20:08:53.597 [DEBUG] [signSucReturnRouteMessageClass:46  ]- NODE 2: Got AssignSucReturnRoute response.
2015-02-08 20:08:53.597 [DEBUG] [signSucReturnRouteMessageClass:49  ]- NODE 2: AssignSucReturnRoute operation started.
2015-02-08 20:08:53.598 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:55  ]- Sent message Message: class = AssignSucReturnRoute (0x51), type = Request (0x00), payload = 02 DE 
2015-02-08 20:08:53.598 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:56  ]- Recv message Message: class = AssignSucReturnRoute (0x51), type = Response (0x01), payload = 01 
2015-02-08 20:08:53.598 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:57  ]- Checking transaction complete: class=AssignSucReturnRoute, expected=AssignSucReturnRoute, cancelled=false
2015-02-08 20:08:53.599 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:60  ]-          transaction complete!
2015-02-08 20:08:53.599 [DEBUG] [b.z.i.protocol.ZWaveController:508 ]- Notifying event listeners
2015-02-08 20:08:53.599 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveActiveBinding@c49f1
2015-02-08 20:08:53.599 [DEBUG] [.z.internal.ZWaveActiveBinding:431 ]- ZwaveIncomingEvent
2015-02-08 20:08:53.600 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveNetworkMonitor@15a61ee
2015-02-08 20:08:53.600 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.config.ZWaveConfiguration@8a17b0
2015-02-08 20:08:53.600 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@15885a7
2015-02-08 20:08:53.600 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16b96f7
2015-02-08 20:08:53.601 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@48531b
2015-02-08 20:08:53.601 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16629df
2015-02-08 20:08:53.601 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@17fb691
2015-02-08 20:08:53.601 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@136f0df
2015-02-08 20:08:53.601 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@f136f2
2015-02-08 20:08:53.602 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@14b396f
2015-02-08 20:08:53.602 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@82d26f
2015-02-08 20:08:53.602 [TRACE] [b.z.i.protocol.ZWaveController:234 ]- Released. Transaction completed permit count -> 1
2015-02-08 20:08:53.602 [DEBUG] [WaveController$ZWaveSendThread:1193]- Response processed after 36ms/2675ms.
2015-02-08 20:08:53.603 [TRACE] [WaveController$ZWaveSendThread:1194]- Acquired. Transaction completed permit count -> 0
2015-02-08 20:08:54.110 [TRACE] [eController$ZWaveReceiveThread:1326]- Reading message finished
2015-02-08 20:08:54.111 [DEBUG] [eController$ZWaveReceiveThread:1327]- Receive Message = 01 05 00 51 DE 01 74 
2015-02-08 20:08:54.111 [TRACE] [o.b.z.i.protocol.SerialMessage:135 ]- NODE 255: Creating new SerialMessage from buffer = 01 05 00 51 DE 01 74 
2015-02-08 20:08:54.111 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0x74
2015-02-08 20:08:54.112 [TRACE] [o.b.z.i.protocol.SerialMessage:139 ]- NODE 255: Message checksum calculated = 0x74, received = 0x74
2015-02-08 20:08:54.112 [TRACE] [o.b.z.i.protocol.SerialMessage:141 ]- NODE 255: Checksum matched
2015-02-08 20:08:54.112 [TRACE] [o.b.z.i.protocol.SerialMessage:152 ]- NODE 255: Message payload = DE 01 
2015-02-08 20:08:54.112 [TRACE] [eController$ZWaveReceiveThread:1246]- Message is valid, sending ACK
2015-02-08 20:08:54.113 [TRACE] [b.z.i.protocol.ZWaveController:170 ]- Incoming message to process
2015-02-08 20:08:54.113 [DEBUG] [b.z.i.protocol.ZWaveController:171 ]- Message: class = AssignSucReturnRoute (0x51), type = Request (0x00), payload = DE 01 
2015-02-08 20:08:54.113 [TRACE] [b.z.i.protocol.ZWaveController:191 ]- Incoming Message type = REQUEST
2015-02-08 20:08:54.114 [DEBUG] [signSucReturnRouteMessageClass:64  ]- NODE 2: Got AssignSucReturnRoute request.
2015-02-08 20:08:54.114 [ERROR] [signSucReturnRouteMessageClass:67  ]- NODE 2: Assign SUC return routes failed with error 0x1.
2015-02-08 20:08:54.114 [DEBUG] [b.z.i.protocol.ZWaveController:508 ]- Notifying event listeners
2015-02-08 20:08:54.114 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveActiveBinding@c49f1
2015-02-08 20:08:54.115 [DEBUG] [.z.internal.ZWaveActiveBinding:431 ]- ZwaveIncomingEvent
2015-02-08 20:08:54.115 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveNetworkMonitor@15a61ee
2015-02-08 20:08:54.115 [DEBUG] [z.internal.ZWaveNetworkMonitor:587 ]- NODE 2: Network heal EVENT
2015-02-08 20:08:54.115 [DEBUG] [z.internal.ZWaveNetworkMonitor:606 ]- NODE 2: Network heal received FAILURE event
2015-02-08 20:08:54.116 [DEBUG] [z.internal.ZWaveNetworkMonitor:472 ]- NODE 2: Heal is setting SUC route.
2015-02-08 20:08:54.116 [DEBUG] [b.z.i.protocol.ZWaveController:866 ]- Callback ID = 223
2015-02-08 20:08:54.116 [DEBUG] [signSucReturnRouteMessageClass:29  ]- NODE 2: Assigning SUC return route
2015-02-08 20:08:54.117 [DEBUG] [o.b.z.i.protocol.SerialMessage:108 ]- NODE 255: Creating empty message of class = AssignSucReturnRoute (0x51), type = Request (0x00)
2015-02-08 20:08:54.117 [DEBUG] [b.z.i.protocol.ZWaveController:493 ]- Enqueueing message. Queue length = 1
2015-02-08 20:08:54.117 [DEBUG] [WaveController$ZWaveSendThread:1091]- Took message from queue for sending. Queue length = 0
2015-02-08 20:08:54.117 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.config.ZWaveConfiguration@8a17b0
2015-02-08 20:08:54.117 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0x76
2015-02-08 20:08:54.118 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@15885a7
2015-02-08 20:08:54.118 [DEBUG] [o.b.z.i.protocol.SerialMessage:232 ]- Assembled message buffer = 01 05 00 51 02 DF 76 
2015-02-08 20:08:54.118 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16b96f7
2015-02-08 20:08:54.119 [DEBUG] [WaveController$ZWaveSendThread:1136]- NODE 255: Sending REQUEST Message = 01 05 00 51 02 DF 76 
2015-02-08 20:08:54.119 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@48531b
2015-02-08 20:08:54.119 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16629df
2015-02-08 20:08:54.119 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@17fb691
2015-02-08 20:08:54.120 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@136f0df
2015-02-08 20:08:54.120 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@f136f2
2015-02-08 20:08:54.120 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@14b396f
2015-02-08 20:08:54.120 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@82d26f
2015-02-08 20:08:54.121 [TRACE] [eController$ZWaveReceiveThread:1332]- Received ACK
2015-02-08 20:08:54.146 [TRACE] [eController$ZWaveReceiveThread:1326]- Reading message finished
2015-02-08 20:08:54.147 [DEBUG] [eController$ZWaveReceiveThread:1327]- Receive Message = 01 04 01 51 01 AA 
2015-02-08 20:08:54.147 [TRACE] [o.b.z.i.protocol.SerialMessage:135 ]- NODE 255: Creating new SerialMessage from buffer = 01 04 01 51 01 AA 
2015-02-08 20:08:54.147 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0xAA
2015-02-08 20:08:54.148 [TRACE] [o.b.z.i.protocol.SerialMessage:139 ]- NODE 255: Message checksum calculated = 0xAA, received = 0xAA
2015-02-08 20:08:54.148 [TRACE] [o.b.z.i.protocol.SerialMessage:141 ]- NODE 255: Checksum matched
2015-02-08 20:08:54.148 [TRACE] [o.b.z.i.protocol.SerialMessage:152 ]- NODE 255: Message payload = 01 
2015-02-08 20:08:54.148 [TRACE] [eController$ZWaveReceiveThread:1246]- Message is valid, sending ACK
2015-02-08 20:08:54.149 [TRACE] [b.z.i.protocol.ZWaveController:170 ]- Incoming message to process
2015-02-08 20:08:54.149 [DEBUG] [b.z.i.protocol.ZWaveController:171 ]- Message: class = AssignSucReturnRoute (0x51), type = Response (0x01), payload = 01 
2015-02-08 20:08:54.149 [TRACE] [b.z.i.protocol.ZWaveController:225 ]- Incoming Message type = RESPONSE
2015-02-08 20:08:54.150 [DEBUG] [signSucReturnRouteMessageClass:46  ]- NODE 2: Got AssignSucReturnRoute response.
2015-02-08 20:08:54.150 [DEBUG] [signSucReturnRouteMessageClass:49  ]- NODE 2: AssignSucReturnRoute operation started.
2015-02-08 20:08:54.150 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:55  ]- Sent message Message: class = AssignSucReturnRoute (0x51), type = Request (0x00), payload = 02 DF 
2015-02-08 20:08:54.151 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:56  ]- Recv message Message: class = AssignSucReturnRoute (0x51), type = Response (0x01), payload = 01 
2015-02-08 20:08:54.151 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:57  ]- Checking transaction complete: class=AssignSucReturnRoute, expected=AssignSucReturnRoute, cancelled=false
2015-02-08 20:08:54.151 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:60  ]-          transaction complete!
2015-02-08 20:08:54.151 [DEBUG] [b.z.i.protocol.ZWaveController:508 ]- Notifying event listeners
2015-02-08 20:08:54.152 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveActiveBinding@c49f1
2015-02-08 20:08:54.152 [DEBUG] [.z.internal.ZWaveActiveBinding:431 ]- ZwaveIncomingEvent
2015-02-08 20:08:54.152 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveNetworkMonitor@15a61ee
2015-02-08 20:08:54.152 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.config.ZWaveConfiguration@8a17b0
2015-02-08 20:08:54.152 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@15885a7
2015-02-08 20:08:54.153 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16b96f7
2015-02-08 20:08:54.153 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@48531b
2015-02-08 20:08:54.153 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16629df
2015-02-08 20:08:54.154 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@17fb691
2015-02-08 20:08:54.154 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@136f0df
2015-02-08 20:08:54.154 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@f136f2
2015-02-08 20:08:54.154 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@14b396f
2015-02-08 20:08:54.155 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@82d26f
2015-02-08 20:08:54.155 [TRACE] [b.z.i.protocol.ZWaveController:234 ]- Released. Transaction completed permit count -> 1
2015-02-08 20:08:54.155 [DEBUG] [WaveController$ZWaveSendThread:1193]- Response processed after 36ms/2675ms.
2015-02-08 20:08:54.155 [TRACE] [WaveController$ZWaveSendThread:1194]- Acquired. Transaction completed permit count -> 0
2015-02-08 20:08:54.602 [TRACE] [eController$ZWaveReceiveThread:1326]- Reading message finished
2015-02-08 20:08:54.603 [DEBUG] [eController$ZWaveReceiveThread:1327]- Receive Message = 01 05 00 51 DF 01 75 
2015-02-08 20:08:54.603 [TRACE] [o.b.z.i.protocol.SerialMessage:135 ]- NODE 255: Creating new SerialMessage from buffer = 01 05 00 51 DF 01 75 
2015-02-08 20:08:54.604 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0x75
2015-02-08 20:08:54.604 [TRACE] [o.b.z.i.protocol.SerialMessage:139 ]- NODE 255: Message checksum calculated = 0x75, received = 0x75
2015-02-08 20:08:54.604 [TRACE] [o.b.z.i.protocol.SerialMessage:141 ]- NODE 255: Checksum matched
2015-02-08 20:08:54.605 [TRACE] [o.b.z.i.protocol.SerialMessage:152 ]- NODE 255: Message payload = DF 01 
2015-02-08 20:08:54.605 [TRACE] [eController$ZWaveReceiveThread:1246]- Message is valid, sending ACK
2015-02-08 20:08:54.606 [TRACE] [b.z.i.protocol.ZWaveController:170 ]- Incoming message to process
2015-02-08 20:08:54.606 [DEBUG] [b.z.i.protocol.ZWaveController:171 ]- Message: class = AssignSucReturnRoute (0x51), type = Request (0x00), payload = DF 01 
2015-02-08 20:08:54.606 [TRACE] [b.z.i.protocol.ZWaveController:191 ]- Incoming Message type = REQUEST
2015-02-08 20:08:54.607 [DEBUG] [signSucReturnRouteMessageClass:64  ]- NODE 2: Got AssignSucReturnRoute request.
2015-02-08 20:08:54.607 [ERROR] [signSucReturnRouteMessageClass:67  ]- NODE 2: Assign SUC return routes failed with error 0x1.
2015-02-08 20:08:54.608 [DEBUG] [b.z.i.protocol.ZWaveController:508 ]- Notifying event listeners
2015-02-08 20:08:54.608 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveActiveBinding@c49f1
2015-02-08 20:08:54.608 [DEBUG] [.z.internal.ZWaveActiveBinding:431 ]- ZwaveIncomingEvent
2015-02-08 20:08:54.608 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveNetworkMonitor@15a61ee
2015-02-08 20:08:54.609 [DEBUG] [z.internal.ZWaveNetworkMonitor:587 ]- NODE 2: Network heal EVENT
2015-02-08 20:08:54.609 [DEBUG] [z.internal.ZWaveNetworkMonitor:606 ]- NODE 2: Network heal received FAILURE event
2015-02-08 20:08:54.609 [DEBUG] [z.internal.ZWaveNetworkMonitor:472 ]- NODE 2: Heal is setting SUC route.
2015-02-08 20:08:54.610 [DEBUG] [b.z.i.protocol.ZWaveController:866 ]- Callback ID = 224
2015-02-08 20:08:54.610 [DEBUG] [signSucReturnRouteMessageClass:29  ]- NODE 2: Assigning SUC return route
2015-02-08 20:08:54.610 [DEBUG] [o.b.z.i.protocol.SerialMessage:108 ]- NODE 255: Creating empty message of class = AssignSucReturnRoute (0x51), type = Request (0x00)
2015-02-08 20:08:54.611 [DEBUG] [b.z.i.protocol.ZWaveController:493 ]- Enqueueing message. Queue length = 1
2015-02-08 20:08:54.611 [DEBUG] [WaveController$ZWaveSendThread:1091]- Took message from queue for sending. Queue length = 0
2015-02-08 20:08:54.611 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.config.ZWaveConfiguration@8a17b0
2015-02-08 20:08:54.612 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0x49
2015-02-08 20:08:54.612 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@15885a7
2015-02-08 20:08:54.612 [DEBUG] [o.b.z.i.protocol.SerialMessage:232 ]- Assembled message buffer = 01 05 00 51 02 E0 49 
2015-02-08 20:08:54.612 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16b96f7
2015-02-08 20:08:54.613 [DEBUG] [WaveController$ZWaveSendThread:1136]- NODE 255: Sending REQUEST Message = 01 05 00 51 02 E0 49 
2015-02-08 20:08:54.613 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@48531b
2015-02-08 20:08:54.613 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16629df
2015-02-08 20:08:54.613 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@17fb691
2015-02-08 20:08:54.614 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@136f0df
2015-02-08 20:08:54.614 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@f136f2
2015-02-08 20:08:54.614 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@14b396f
2015-02-08 20:08:54.614 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@82d26f
2015-02-08 20:08:54.615 [TRACE] [eController$ZWaveReceiveThread:1332]- Received ACK
2015-02-08 20:08:54.640 [TRACE] [eController$ZWaveReceiveThread:1326]- Reading message finished
2015-02-08 20:08:54.641 [DEBUG] [eController$ZWaveReceiveThread:1327]- Receive Message = 01 04 01 51 01 AA 
2015-02-08 20:08:54.641 [TRACE] [o.b.z.i.protocol.SerialMessage:135 ]- NODE 255: Creating new SerialMessage from buffer = 01 04 01 51 01 AA 
2015-02-08 20:08:54.641 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0xAA
2015-02-08 20:08:54.642 [TRACE] [o.b.z.i.protocol.SerialMessage:139 ]- NODE 255: Message checksum calculated = 0xAA, received = 0xAA
2015-02-08 20:08:54.642 [TRACE] [o.b.z.i.protocol.SerialMessage:141 ]- NODE 255: Checksum matched
2015-02-08 20:08:54.642 [TRACE] [o.b.z.i.protocol.SerialMessage:152 ]- NODE 255: Message payload = 01 
2015-02-08 20:08:54.642 [TRACE] [eController$ZWaveReceiveThread:1246]- Message is valid, sending ACK
2015-02-08 20:08:54.643 [TRACE] [b.z.i.protocol.ZWaveController:170 ]- Incoming message to process
2015-02-08 20:08:54.643 [DEBUG] [b.z.i.protocol.ZWaveController:171 ]- Message: class = AssignSucReturnRoute (0x51), type = Response (0x01), payload = 01 
2015-02-08 20:08:54.644 [TRACE] [b.z.i.protocol.ZWaveController:225 ]- Incoming Message type = RESPONSE
2015-02-08 20:08:54.644 [DEBUG] [signSucReturnRouteMessageClass:46  ]- NODE 2: Got AssignSucReturnRoute response.
2015-02-08 20:08:54.644 [DEBUG] [signSucReturnRouteMessageClass:49  ]- NODE 2: AssignSucReturnRoute operation started.
2015-02-08 20:08:54.644 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:55  ]- Sent message Message: class = AssignSucReturnRoute (0x51), type = Request (0x00), payload = 02 E0 
2015-02-08 20:08:54.645 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:56  ]- Recv message Message: class = AssignSucReturnRoute (0x51), type = Response (0x01), payload = 01 
2015-02-08 20:08:54.645 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:57  ]- Checking transaction complete: class=AssignSucReturnRoute, expected=AssignSucReturnRoute, cancelled=false
2015-02-08 20:08:54.645 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:60  ]-          transaction complete!
2015-02-08 20:08:54.646 [DEBUG] [b.z.i.protocol.ZWaveController:508 ]- Notifying event listeners
2015-02-08 20:08:54.646 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveActiveBinding@c49f1
2015-02-08 20:08:54.646 [DEBUG] [.z.internal.ZWaveActiveBinding:431 ]- ZwaveIncomingEvent
2015-02-08 20:08:54.646 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveNetworkMonitor@15a61ee
2015-02-08 20:08:54.647 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.config.ZWaveConfiguration@8a17b0
2015-02-08 20:08:54.647 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@15885a7
2015-02-08 20:08:54.647 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16b96f7
2015-02-08 20:08:54.647 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@48531b
2015-02-08 20:08:54.648 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16629df
2015-02-08 20:08:54.648 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@17fb691
2015-02-08 20:08:54.648 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@136f0df
2015-02-08 20:08:54.648 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@f136f2
2015-02-08 20:08:54.649 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@14b396f
2015-02-08 20:08:54.649 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@82d26f
2015-02-08 20:08:54.649 [TRACE] [b.z.i.protocol.ZWaveController:234 ]- Released. Transaction completed permit count -> 1
2015-02-08 20:08:54.649 [DEBUG] [WaveController$ZWaveSendThread:1193]- Response processed after 36ms/2675ms.
2015-02-08 20:08:54.650 [TRACE] [WaveController$ZWaveSendThread:1194]- Acquired. Transaction completed permit count -> 0
2015-02-08 20:08:55.156 [TRACE] [eController$ZWaveReceiveThread:1326]- Reading message finished
2015-02-08 20:08:55.157 [DEBUG] [eController$ZWaveReceiveThread:1327]- Receive Message = 01 05 00 51 E0 01 4A 
2015-02-08 20:08:55.157 [TRACE] [o.b.z.i.protocol.SerialMessage:135 ]- NODE 255: Creating new SerialMessage from buffer = 01 05 00 51 E0 01 4A 
2015-02-08 20:08:55.157 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0x4A
2015-02-08 20:08:55.158 [TRACE] [o.b.z.i.protocol.SerialMessage:139 ]- NODE 255: Message checksum calculated = 0x4A, received = 0x4A
2015-02-08 20:08:55.158 [TRACE] [o.b.z.i.protocol.SerialMessage:141 ]- NODE 255: Checksum matched
2015-02-08 20:08:55.158 [TRACE] [o.b.z.i.protocol.SerialMessage:152 ]- NODE 255: Message payload = E0 01 
2015-02-08 20:08:55.159 [TRACE] [eController$ZWaveReceiveThread:1246]- Message is valid, sending ACK
2015-02-08 20:08:55.160 [TRACE] [b.z.i.protocol.ZWaveController:170 ]- Incoming message to process
2015-02-08 20:08:55.161 [DEBUG] [b.z.i.protocol.ZWaveController:171 ]- Message: class = AssignSucReturnRoute (0x51), type = Request (0x00), payload = E0 01 
2015-02-08 20:08:55.161 [TRACE] [b.z.i.protocol.ZWaveController:191 ]- Incoming Message type = REQUEST
2015-02-08 20:08:55.162 [DEBUG] [signSucReturnRouteMessageClass:64  ]- NODE 2: Got AssignSucReturnRoute request.
2015-02-08 20:08:55.162 [ERROR] [signSucReturnRouteMessageClass:67  ]- NODE 2: Assign SUC return routes failed with error 0x1.
2015-02-08 20:08:55.162 [DEBUG] [b.z.i.protocol.ZWaveController:508 ]- Notifying event listeners
2015-02-08 20:08:55.162 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveActiveBinding@c49f1
2015-02-08 20:08:55.163 [DEBUG] [.z.internal.ZWaveActiveBinding:431 ]- ZwaveIncomingEvent
2015-02-08 20:08:55.163 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveNetworkMonitor@15a61ee
2015-02-08 20:08:55.163 [DEBUG] [z.internal.ZWaveNetworkMonitor:587 ]- NODE 2: Network heal EVENT
2015-02-08 20:08:55.163 [DEBUG] [z.internal.ZWaveNetworkMonitor:606 ]- NODE 2: Network heal received FAILURE event
2015-02-08 20:08:55.164 [DEBUG] [z.internal.ZWaveNetworkMonitor:472 ]- NODE 2: Heal is setting SUC route.
2015-02-08 20:08:55.164 [DEBUG] [b.z.i.protocol.ZWaveController:866 ]- Callback ID = 225
2015-02-08 20:08:55.164 [DEBUG] [signSucReturnRouteMessageClass:29  ]- NODE 2: Assigning SUC return route
2015-02-08 20:08:55.165 [DEBUG] [o.b.z.i.protocol.SerialMessage:108 ]- NODE 255: Creating empty message of class = AssignSucReturnRoute (0x51), type = Request (0x00)
2015-02-08 20:08:55.165 [DEBUG] [b.z.i.protocol.ZWaveController:493 ]- Enqueueing message. Queue length = 1
2015-02-08 20:08:55.165 [DEBUG] [WaveController$ZWaveSendThread:1091]- Took message from queue for sending. Queue length = 0
2015-02-08 20:08:55.165 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.config.ZWaveConfiguration@8a17b0
2015-02-08 20:08:55.165 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0x48
2015-02-08 20:08:55.166 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@15885a7
2015-02-08 20:08:55.166 [DEBUG] [o.b.z.i.protocol.SerialMessage:232 ]- Assembled message buffer = 01 05 00 51 02 E1 48 
2015-02-08 20:08:55.166 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16b96f7
2015-02-08 20:08:55.166 [DEBUG] [WaveController$ZWaveSendThread:1136]- NODE 255: Sending REQUEST Message = 01 05 00 51 02 E1 48 
2015-02-08 20:08:55.167 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@48531b
2015-02-08 20:08:55.167 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16629df
2015-02-08 20:08:55.167 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@17fb691
2015-02-08 20:08:55.168 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@136f0df
2015-02-08 20:08:55.168 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@f136f2
2015-02-08 20:08:55.168 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@14b396f
2015-02-08 20:08:55.168 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@82d26f
2015-02-08 20:08:55.169 [TRACE] [eController$ZWaveReceiveThread:1332]- Received ACK
2015-02-08 20:08:55.194 [TRACE] [eController$ZWaveReceiveThread:1326]- Reading message finished
2015-02-08 20:08:55.195 [DEBUG] [eController$ZWaveReceiveThread:1327]- Receive Message = 01 04 01 51 01 AA 
2015-02-08 20:08:55.195 [TRACE] [o.b.z.i.protocol.SerialMessage:135 ]- NODE 255: Creating new SerialMessage from buffer = 01 04 01 51 01 AA 
2015-02-08 20:08:55.195 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0xAA
2015-02-08 20:08:55.196 [TRACE] [o.b.z.i.protocol.SerialMessage:139 ]- NODE 255: Message checksum calculated = 0xAA, received = 0xAA
2015-02-08 20:08:55.196 [TRACE] [o.b.z.i.protocol.SerialMessage:141 ]- NODE 255: Checksum matched
2015-02-08 20:08:55.196 [TRACE] [o.b.z.i.protocol.SerialMessage:152 ]- NODE 255: Message payload = 01 
2015-02-08 20:08:55.196 [TRACE] [eController$ZWaveReceiveThread:1246]- Message is valid, sending ACK
2015-02-08 20:08:55.197 [TRACE] [b.z.i.protocol.ZWaveController:170 ]- Incoming message to process
2015-02-08 20:08:55.197 [DEBUG] [b.z.i.protocol.ZWaveController:171 ]- Message: class = AssignSucReturnRoute (0x51), type = Response (0x01), payload = 01 
2015-02-08 20:08:55.198 [TRACE] [b.z.i.protocol.ZWaveController:225 ]- Incoming Message type = RESPONSE
2015-02-08 20:08:55.198 [DEBUG] [signSucReturnRouteMessageClass:46  ]- NODE 2: Got AssignSucReturnRoute response.
2015-02-08 20:08:55.198 [DEBUG] [signSucReturnRouteMessageClass:49  ]- NODE 2: AssignSucReturnRoute operation started.
2015-02-08 20:08:55.198 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:55  ]- Sent message Message: class = AssignSucReturnRoute (0x51), type = Request (0x00), payload = 02 E1 
2015-02-08 20:08:55.199 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:56  ]- Recv message Message: class = AssignSucReturnRoute (0x51), type = Response (0x01), payload = 01 
2015-02-08 20:08:55.199 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:57  ]- Checking transaction complete: class=AssignSucReturnRoute, expected=AssignSucReturnRoute, cancelled=false
2015-02-08 20:08:55.199 [DEBUG] [.z.i.p.s.ZWaveCommandProcessor:60  ]-          transaction complete!
2015-02-08 20:08:55.200 [DEBUG] [b.z.i.protocol.ZWaveController:508 ]- Notifying event listeners
2015-02-08 20:08:55.200 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveActiveBinding@c49f1
2015-02-08 20:08:55.200 [DEBUG] [.z.internal.ZWaveActiveBinding:431 ]- ZwaveIncomingEvent
2015-02-08 20:08:55.200 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveNetworkMonitor@15a61ee
2015-02-08 20:08:55.201 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.config.ZWaveConfiguration@8a17b0
2015-02-08 20:08:55.201 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@15885a7
2015-02-08 20:08:55.201 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16b96f7
2015-02-08 20:08:55.201 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@48531b
2015-02-08 20:08:55.202 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16629df
2015-02-08 20:08:55.202 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@17fb691
2015-02-08 20:08:55.202 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@136f0df
2015-02-08 20:08:55.202 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@f136f2
2015-02-08 20:08:55.203 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@14b396f
2015-02-08 20:08:55.203 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@82d26f
2015-02-08 20:08:55.203 [TRACE] [b.z.i.protocol.ZWaveController:234 ]- Released. Transaction completed permit count -> 1
2015-02-08 20:08:55.203 [DEBUG] [WaveController$ZWaveSendThread:1193]- Response processed after 36ms/2675ms.
2015-02-08 20:08:55.204 [TRACE] [WaveController$ZWaveSendThread:1194]- Acquired. Transaction completed permit count -> 0
2015-02-08 20:08:55.654 [TRACE] [eController$ZWaveReceiveThread:1326]- Reading message finished
2015-02-08 20:08:55.655 [DEBUG] [eController$ZWaveReceiveThread:1327]- Receive Message = 01 05 00 51 E1 01 4B 
2015-02-08 20:08:55.655 [TRACE] [o.b.z.i.protocol.SerialMessage:135 ]- NODE 255: Creating new SerialMessage from buffer = 01 05 00 51 E1 01 4B 
2015-02-08 20:08:55.656 [TRACE] [o.b.z.i.protocol.SerialMessage:178 ]- Calculated checksum = 0x4B
2015-02-08 20:08:55.656 [TRACE] [o.b.z.i.protocol.SerialMessage:139 ]- NODE 255: Message checksum calculated = 0x4B, received = 0x4B
2015-02-08 20:08:55.656 [TRACE] [o.b.z.i.protocol.SerialMessage:141 ]- NODE 255: Checksum matched
2015-02-08 20:08:55.656 [TRACE] [o.b.z.i.protocol.SerialMessage:152 ]- NODE 255: Message payload = E1 01 
2015-02-08 20:08:55.657 [TRACE] [eController$ZWaveReceiveThread:1246]- Message is valid, sending ACK
2015-02-08 20:08:55.657 [TRACE] [b.z.i.protocol.ZWaveController:170 ]- Incoming message to process
2015-02-08 20:08:55.658 [DEBUG] [b.z.i.protocol.ZWaveController:171 ]- Message: class = AssignSucReturnRoute (0x51), type = Request (0x00), payload = E1 01 
2015-02-08 20:08:55.658 [TRACE] [b.z.i.protocol.ZWaveController:191 ]- Incoming Message type = REQUEST
2015-02-08 20:08:55.658 [DEBUG] [signSucReturnRouteMessageClass:64  ]- NODE 2: Got AssignSucReturnRoute request.
2015-02-08 20:08:55.658 [ERROR] [signSucReturnRouteMessageClass:67  ]- NODE 2: Assign SUC return routes failed with error 0x1.
2015-02-08 20:08:55.659 [DEBUG] [b.z.i.protocol.ZWaveController:508 ]- Notifying event listeners
2015-02-08 20:08:55.659 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveActiveBinding@c49f1
2015-02-08 20:08:55.659 [DEBUG] [.z.internal.ZWaveActiveBinding:431 ]- ZwaveIncomingEvent
2015-02-08 20:08:55.659 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.ZWaveNetworkMonitor@15a61ee
2015-02-08 20:08:55.660 [DEBUG] [z.internal.ZWaveNetworkMonitor:587 ]- NODE 2: Network heal EVENT
2015-02-08 20:08:55.660 [DEBUG] [z.internal.ZWaveNetworkMonitor:606 ]- NODE 2: Network heal received FAILURE event
2015-02-08 20:08:55.660 [DEBUG] [z.internal.ZWaveNetworkMonitor:422 ]- NODE 2: Maximum retries in state SETSUCROUTE
2015-02-08 20:08:55.660 [DEBUG] [z.internal.ZWaveNetworkMonitor:431 ]- NODE 2: Network heal has exceeded maximum retries!
2015-02-08 20:08:55.664 [TRACE] [.b.z.i.p.i.ZWaveNodeSerializer:50  ]- Initializing ZWaveNodeSerializer.
2015-02-08 20:08:55.680 [TRACE] [.b.z.i.p.i.ZWaveNodeSerializer:76  ]- Initialized ZWaveNodeSerializer.
2015-02-08 20:08:55.681 [DEBUG] [.b.z.i.p.i.ZWaveNodeSerializer:90  ]- NODE 2: Serializing to file etc/zwave/node2.xml
2015-02-08 20:08:55.695 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.config.ZWaveConfiguration@8a17b0
2015-02-08 20:08:55.695 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@15885a7
2015-02-08 20:08:55.696 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16b96f7
2015-02-08 20:08:55.696 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@48531b
2015-02-08 20:08:55.696 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@16629df
2015-02-08 20:08:55.696 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@17fb691
2015-02-08 20:08:55.697 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@136f0df
2015-02-08 20:08:55.697 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@f136f2
2015-02-08 20:08:55.697 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.commandclass.ZWaveWakeUpCommandClass@14b396f
2015-02-08 20:08:55.697 [TRACE] [b.z.i.protocol.ZWaveController:511 ]- Notifying org.openhab.binding.zwave.internal.protocol.initialization.ZWaveNodeStageAdvancer@82d26f
2015-02-08 20:08:57.304 [TRACE] [veController$WatchDogTimerTask:1392]- Watchdog: Checking Serial threads
2015-02-08 20:09:07.304 [TRACE] [veController$WatchDogTimerTask:1392]- Watchdog: Checking Serial threads
petrklus commented 9 years ago

Please see full log attached (it may be truncated as it's rotated daily due to being TRACE verbosity) zwave.log.zip | uploaded via ZenHub

Also, the Node 2 is the only one marked DEAD by the binding at this moment:

image

cdjackson commented 9 years ago

What’s happening is that the device isn’t responding to the message from the controller -: NODE 2: SendData Request. CallBack ID = 219, Status = Transmission complete, no ACK received(1) So, this causes the binding to do a heal.

If this is happening all the time, then it’s possible the item definition is incorrect. What is the device, and can you post the XML associated with node 2.

petrklus commented 9 years ago

It's Fibaro Double Relay switch - and it still works absolutely fine, only sometimes commands get queued up because of the constant heal. Please find attached the node2.xml

node2.xml | uploaded via ZenHub

cdjackson commented 9 years ago

It's Fibaro Double Relay switch - and it still works absolutely fine, only sometimes commands get queued up because of the constant heal. Please find attached the node2.xml

The question is why it’s doing the heal - the ultimate answer is because the device isn’t responding to messages (at least in the log you sent). This causes it to timeout and then there’s a heal. So, we need to find out why the device doesn’t respond. Either the item config is wrong (but probably not), or maybe the device is at the edge of reception? Is it always relay 2 that fails? or does relay 1 also fail occasionally? There’s no reason from a binding perspective why relay 2 is any different than relay 1...

petrklus commented 9 years ago

No, it is quite close actually - probably just approx. 5m away from the stick, in between node 1 and the stick actually.

If I issue a command, it reacts immediately. For example, when I switch the lights ON, they respond immediately, but then the OFF may get delayed as I can see that after issuing ON, it starts pushing through the HEAL, which queues the OFF.

cdjackson commented 9 years ago

So, this node is not responding to any messages. Clearly it’s receiving them, but in the log you sent, we sent it a number of messages and they all timed out, so for some reason we’re not getting the response.

NODE 2: SendData Request. CallBack ID = 219, Status = Transmission complete, no ACK received(1)

petrklus commented 9 years ago

@cdjackson Odd - I would be inclined to think that it was a transmission problem if the node was not so close. However, it seems to have fixed itself now - any ideas if it could be anything more than just interference?

cdjackson commented 9 years ago

It could be interference - I’m not sure. All we can say is that the device was obviously receiving the commands from the controller (since the light went on) but the controller wasn’t receiving the ACK from the device (since we got the NO ACK response). Other than that, I’m not sure - I’m pretty sure it’s not a binding issue though...