OH2 Z-Wave refactoring and testing... and SECURITY

OH 2.3 S1273, Z-Wave v 2.3.0.201805072038

I have also 2 nodes which appear as failed but something strange is happening at the same time (I think… not 100% sure)… OH2 is still getting info from them and updates the states of the items…

some log entries:

2018-05-11 17:42:04.987 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.987 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!

more complete log
2018-05-11 17:42:04.951 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 10: Requesting IsFailedNode status from controller.
2018-05-11 17:42:04.952 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@6398d665
2018-05-11 17:42:04.953 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2018-05-11 17:42:04.954 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
2018-05-11 17:42:04.955 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2018-05-11 17:42:04.956 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.956 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Node not awake!
2018-05-11 17:42:04.957 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.958 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.959 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.960 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.961 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.962 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.963 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.964 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.964 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.964 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.965 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.965 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.965 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.966 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.966 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.967 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.967 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.967 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.968 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.968 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.968 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.969 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.969 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.969 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.970 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.970 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.970 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.971 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.971 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.971 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.972 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.972 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.973 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.973 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.973 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.974 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.974 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.974 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.975 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.975 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.975 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.976 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.976 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.976 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.976 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.976 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.976 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.976 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.977 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.977 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.977 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.978 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.978 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.978 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.978 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.978 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.978 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.979 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.979 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.979 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.979 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.979 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.979 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.980 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.980 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.980 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.980 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.980 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.980 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.980 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.981 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.981 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.981 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.981 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.981 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.981 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.981 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.982 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.982 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.983 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.983 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.983 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.983 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.983 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.983 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.983 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.984 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.984 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.984 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.984 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.984 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.984 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.984 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.985 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.985 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.985 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.985 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.985 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.985 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.985 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.986 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.986 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.986 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.986 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.986 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.987 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.987 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.987 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.987 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:04.987 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!
2018-05-11 17:42:04.987 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
2018-05-11 17:42:04.988 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
2018-05-11 17:42:04.988 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating empty message of class = IsFailedNodeID (0x62), type = Request
2018-05-11 17:42:04.988 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -109
2018-05-11 17:42:04.988 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 0A 93 
2018-05-11 17:42:04.988 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 0A 93 
2018-05-11 17:42:04.989 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2018-05-11 17:42:04.989 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 526: Transaction Start type IsFailedNodeID 
2018-05-11 17:42:04.989 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 526: [WAIT_RESPONSE] requiresResponse=true callback: 0
2018-05-11 17:42:04.989 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
2018-05-11 17:42:04.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
2018-05-11 17:42:04.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
2018-05-11 17:42:04.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri May 11 17:42:06 EEST 2018 - 2000ms
2018-05-11 17:42:04.990 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 526: [WAIT_RESPONSE] requiresResponse=true callback: 0
2018-05-11 17:42:04.991 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2018-05-11 17:42:04.991 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 06 
2018-05-11 17:42:04.991 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-05-11 17:42:04.992 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-05-11 17:42:04.992 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Received SOF
2018-05-11 17:42:04.992 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 01 99 
2018-05-11 17:42:04.993 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Creating new SerialMessage from buffer = 01 04 01 62 01 99 
2018-05-11 17:42:04.993 [TRACE] [wave.internal.protocol.SerialMessage] - Calculated checksum = -103
2018-05-11 17:42:04.993 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2018-05-11 17:42:04.993 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Checksum matched
2018-05-11 17:42:04.993 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 526: [WAIT_RESPONSE] requiresResponse=true callback: 0
2018-05-11 17:42:04.993 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2018-05-11 17:42:04.993 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-05-11 17:42:04.994 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2018-05-11 17:42:04.993 [TRACE] [wave.internal.protocol.SerialMessage] - NODE 255: Message payload = 01 
2018-05-11 17:42:04.994 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Message is valid, sending ACK
2018-05-11 17:42:04.994 [TRACE] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
2018-05-11 17:42:04.994 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01 
2018-05-11 17:42:04.994 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01 
2018-05-11 17:42:04.994 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2018-05-11 17:42:04.995 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri May 11 17:42:06 EEST 2018 - 1995ms
2018-05-11 17:42:04.997 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 2: Requesting IsFailedNode status from controller.
2018-05-11 17:42:04.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@15413f3a
2018-05-11 17:42:04.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
2018-05-11 17:42:04.997 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
2018-05-11 17:42:04.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start
2018-05-11 17:42:04.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2018-05-11 17:42:04.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2018-05-11 17:42:04.998 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri May 11 17:42:06 EEST 2018 - 1992ms
2018-05-11 17:42:04.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
2018-05-11 17:42:04.999 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
2018-05-11 17:42:05.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri May 11 17:42:06 EEST 2018 - 1990ms
2018-05-11 17:42:05.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01 
2018-05-11 17:42:05.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 526: [WAIT_RESPONSE] requiresResponse=true callback: 0
2018-05-11 17:42:05.000 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2018-05-11 17:42:05.001 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 526: [WAIT_RESPONSE] requiresResponse=true callback: 0
2018-05-11 17:42:05.001 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01 
2018-05-11 17:42:05.001 [TRACE] [ve.internal.protocol.ZWaveController] - Incoming Message type = RESPONSE
2018-05-11 17:42:05.001 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 10: Is currently marked as failed by the controller!
2018-05-11 17:42:05.002 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 526: Transaction COMPLETED
2018-05-11 17:42:05.002 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 526: TransactionAdvance ST: DONE
2018-05-11 17:42:05.002 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 526: TransactionAdvance WT: null {}
2018-05-11 17:42:05.002 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 526: TransactionAdvance RX: Message: class=IsFailedNodeID[98], type=Response[1], dest=255, callback=0, payload=01 
2018-05-11 17:42:05.002 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 526: TransactionAdvance TO: DONE
2018-05-11 17:42:05.003 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Response processed after 14ms
2018-05-11 17:42:05.003 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: TID 526: Transaction completed
2018-05-11 17:42:05.003 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: notifyTransactionResponse TID:526 DONE
2018-05-11 17:42:05.005 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveTransactionCompletedEvent
2018-05-11 17:42:05.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 526: Transaction event listener: DONE: DONE -> 
2018-05-11 17:42:05.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: -- To notify -- COMPLETE
2018-05-11 17:42:05.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ********* Transaction Response Complete -- 526 --
2018-05-11 17:42:05.005 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2018-05-11 17:42:05.006 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 10: Node Init response (0) org.openhab.binding.zwave.internal.protocol.ZWaveTransactionResponse@3eca82e7
2018-05-11 17:42:05.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
2018-05-11 17:42:05.006 [DEBUG] [alization.ZWaveNodeInitStageAdvancer] - NODE 10: Node Init transaction completed with response COMPLETE
2018-05-11 17:42:05.007 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 8: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:05.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 8: Node not awake!
2018-05-11 17:42:05.007 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 2: listening == false, frequentlyListening == false, awake == false
2018-05-11 17:42:05.007 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 2: Node not awake!

The (strange!) issue is that the controller reports the device as failed. When I implemented this, it seemed to be the best thing to do - in theory the controller should have the best information about the state of a device. However this has proved to be unreliable, and I will likely change this back to the old implementation.

1 Like

i discussed the same thing couple months ago with you @chris
since that time quite a few things are reported as offline even they do communicate with the controller
in the moment when they communicate they switch to online just to be reported as offline a moment later

you said only the controller manages this information and the binding only reads that state from the controller

curious to me is that i never had this for like 2 years and it became worse since we discussed that a few months ago. after a OH reboot I have always new things that behave like described above and need some days/weeks until its ok again.

I was seeing this too for quite a while now, strange thing is since upgrading to zwave development version 20180507 the issue is gone :sunglasses:

This is new for the development binding, that’s why. When I wrote the new binding, this seemed to be a better way of detecting devices being offline - ie to use the controller to report this. The controller maintains a list of devices that are considered dead - the controller SHOULD know this much better than the binding as it has access to information that is not available at higher layers.

However, as has been reported, the controller seems to report incorrect information and I need to change the way this works in the binding - this is quite a bit of work to do, but I will look at it in the near future.

2 Likes

I understood that obviously wrong last time I discussed this Offline issue

It’s actually stated in the very first message in this thread where I list the changes made in this version -:

I’ve also changed the way we’re handling retries and dead nodes. I’ve currently removed retries from the binding – this is because the controller already performs 3 retries, and it’s my feeling that have 3 retries at binding level was probably causing more problems than it solved as it blocks the binding from dealing with other commands for 15 seconds. I also don’t set a device as dead if it times out – only if the controller thinks the device is failed.

@lolodomo I don’t think so. I’m successfully running several ST814’s in my network using a Gen 5 stick. But, I’m still running the binding from the master branch, not the dev branch.

@chris Do you have a time frame for reverting to the old implementation? This is the one thing that’s been keeping me from converting my remaining network to the dev version of the binding?

I will look at this in a few weeks - I want to get this merged into master not too long after 2.3 is released, so it needs to be done in that timeframe.

3 Likes

Hi Chris,

i have update to the OH 2.30 and the z-wave-binding with latest Version. After the update i have many errors with:

2018-05-13 20:49:54.891 [ERROR] [age.AssignSucReturnRouteMessageClass] - NODE 3: AssignSucReturnRoute command failed.

What is the “AssignSucReturnRoute command” and can you fix this?

It is a command to assign a route from a device to another device - it’s normally sent during the heal. I’ve no idea why it’s failing so can’t really comment on how to fix it, sorry. Maybe a debug log will help (but maybe not) - if you provide one I’ll take a look - also please advise what the device is.

As the latest binding now requires Openhab 2.3, I tried to do a clean install of the snapshot, but the offline install seems to fail. I posted details here but no replies. Wondered if anyone reading this thread has any ideas as I’d like to use the updated database in the lastest binding…

There is one major downside with your approach: if you are using the offline kar, uninstalling and reinstalling will not update the zwave snapshot binding, because it will always get the version from the kar file.
I can not find any good reason why to use the offline kar file … except you don’t have an internet connection where you are using your smarthome hardware.

I’m not sure I understand you correctly. Using Openhab 2.2, and the 2.2 addons .kar as well as the zwave binding from this thread I am able to install and use this binding on a machine without internet connectivity. The problem is that, regardless of the binding from this thread, it doesn’t seem possible to install Openhab 2.3 “offline” - although perhaps I am doing something wrong.

I have seen an issue report a while ago where there was an error with the offline install, but can’t find it anymore. Please take a look at the github issues for openHAB and ESH, you may be able to find it and check if it is still open.

Edit: Upps, deleted the original post by accident, sorry :sunglasses:

Well, it did up until this binding started to require Openhab 2.3 :sob:

I don’t think the issue is that the development binding requires the latest version. If you can’t install OH, then that’s not really a problem with the binding. Given that 2.3 is planned for release very soon now, I’d suggest to report it as a bug if you think it’s a bug.

I thought asking in the “installation” category was the right place to start. Where do I report a bug? It could well be I am doing something wrong but the same install process does work with Openhab 2.2 so I guess it either needs to be documented as a change or identified as a bug…

Sure - the forum is good for discussions, but if you really think there’s a bug, then you should actually report a bug in the development issue tracker.

On the github issue lists. I’ve not really followed the problem that you’re having, but possibly in the openhab-distro list -:

Here is the Logfile
Node 2: Eurotronics Spirit Thermostat
Node 3: Eurotronics Spirit Thermostat
Node 4: Fibaro Window/Door Sensor 2