sorry after switching to this latest version of the binding I have a strange behaviour of a couple devices
Try now - I missed something in my 1 line change 
.
still the same…
maybe I was too quick?( took the link in post #1)
That link should be fine. Is there anything in the log?
the log looks like its reading the device as FAILED from the controller and therefore sets it to OFFLINE
I wonder if this is correct as it happens to a few devices that operate nominal and it started to happen after the binding update from today.
so unsure if the controller really marks all these devices as failed or of its a bug?
edit
here is a bit of the log:
14:22:22.741 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 32: Requesting IsFailedNode status from controller.
14:22:22.750 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: sendTransaction org.openhab.binding.zwave.internal.protocol.ZWaveSerialPayload@d3a5e5
14:22:22.766 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Adding to controller queue
14:22:22.771 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 255: Added to queue - size 1
14:22:22.775 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
14:22:22.779 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 18: listening == false, frequentlyListening == false, awake == false
14:22:22.783 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 18: Node not awake!
14:22:22.787 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 28: listening == false, frequentlyListening == false, awake == false
14:22:22.790 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 28: Node not awake!
14:22:22.793 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 19: listening == false, frequentlyListening == false, awake == false
14:22:22.795 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 19: Node not awake!
14:22:22.797 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 15: listening == false, frequentlyListening == false, awake == false
14:22:22.800 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 15: Node not awake!
14:22:22.802 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 11: listening == false, frequentlyListening == false, awake == false
14:22:22.804 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 11: Node not awake!
14:22:22.807 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 36: listening == false, frequentlyListening == false, awake == false
14:22:22.810 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 36: Node not awake!
14:22:22.812 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 14: listening == false, frequentlyListening == false, awake == false
14:22:22.814 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 14: Node not awake!
14:22:22.817 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 17: listening == false, frequentlyListening == false, awake == false
14:22:22.819 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 17: Node not awake!
14:22:22.821 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: listening == false, frequentlyListening == false, awake == false
14:22:22.823 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Node not awake!
14:22:22.826 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 35: listening == false, frequentlyListening == false, awake == false
14:22:22.828 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 35: Node not awake!
14:22:22.831 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction from controllerQueue
14:22:22.833 [DEBUG] [nal.protocol.ZWaveTransactionManager] - getTransactionToSend 6
14:22:22.837 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 04 00 62 20 B9
14:22:22.840 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 255: Sending REQUEST Message = 01 04 00 62 20 B9
14:22:22.843 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
14:22:22.845 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
14:22:22.851 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 436: Transaction Start type IsFailedNodeID
14:22:22.856 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
14:22:22.888 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
14:22:22.892 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0x00], type=ACK[0x02], dest=255, callback=0, payload=
14:22:22.897 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
14:22:22.902 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
14:22:22.857 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 436: [WAIT_RESPONSE] requiresResponse=true callback: 0
14:22:22.910 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
14:22:22.922 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start
14:22:22.895 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 62 01 99
14:22:22.917 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd class: null
14:22:22.931 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Response SENT 6
14:22:22.935 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: expected cmd: null
14:22:22.939 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
14:22:22.945 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage Transactions outstanding: 1
14:22:22.959 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage past lock Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
14:22:22.965 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Dec 29 14:22:24 CET 2017 - 1999ms
14:22:22.978 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage lastTransaction: TID 436: [WAIT_RESPONSE] requiresResponse=true callback: 0
14:22:22.985 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction lastTransaction outstanding...
14:22:22.988 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
14:22:22.996 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Dec 29 14:22:24 CET 2017 - 1966ms
14:22:23.004 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
14:22:23.006 [DEBUG] [nal.protocol.ZWaveTransactionManager] - STOP transaction timer
14:22:23.010 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Start transaction timer to Fri Dec 29 14:22:24 CET 2017 - 1951ms
14:22:23.017 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 436: [WAIT_RESPONSE] requiresResponse=true callback: 0
14:22:23.029 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
14:22:23.035 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 436: [WAIT_RESPONSE] requiresResponse=true callback: 0
14:22:23.041 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=IsFailedNodeID[0x62], type=Response[0x01], dest=255, callback=0, payload=01
14:22:23.047 [DEBUG] [rialmessage.IsFailedNodeMessageClass] - NODE 32: Is currently marked as failed by the controller!
14:22:23.053 [DEBUG] [ve.internal.protocol.ZWaveController] - Notifying event listeners: ZWaveNodeStatusEvent
14:22:23.058 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Got an event from Z-Wave network: ZWaveNodeStatusEvent
14:22:23.063 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 32: Setting OFFLINE
14:22:23.071 [DEBUG] [ve.internal.protocol.ZWaveController] - NODE 32: Node Status event - Node is FAILED
14:22:23.074 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 32: Node is DEAD.
14:22:23.080 [INFO ] [me.event.ThingStatusInfoChangedEvent] - 'zwave:device:15348538564:node32' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): Node is not communicating with controllerI’m confident it’s not a bug - at least not in the binding. I don’t know why the controller would mark the device as failed though - I’ll discuss this with Sigma in the new year.
mhh ok
I added a bit of the log in the post above.
This happens for 5 devices (from 28) now after the NOGET binding update.
I think the check for a failed device was there before todays binding update?
I don’t think it’s related to the NOGET in the database 
Yes - it has always been in this version of the binding (so lets say 1.5 years).
I was not thinking that
Just saying this happens since I replaced the binding with that version from today and wasn’t happening before (with a version from a few days ago)
Since you state the “failed check” is there for ~1.5 yrs I’m still confused why it should start to happen now.
I can switch back to the old JAR and see if its gone again.
edit: maybe not. did not preserve a copy of the old version.
Why not? Given we don’t know why it happens, I think it’s probably totally unrelated to the binding update.
It’s really easy (and common) for people to attribute an issue with a specific change like this, but it’s not necessarily the case. I think you only changed to the dev binding a few days ago, so it may happen anyway…
This check has always been in the development version since the very first version. I’m confident the check is correct (I have the full documentation on this from Sigma) and I will check with them in the new year if they have any ideas. From what I read in the STK docs, it shouldn’t happen…
Updated JAR posted to fix some issues around endpoints and saving - any feedback welcome.
I’m not longer getting NPEs (issue 755) when deleting or assigning associations. However, Habmin still shows this after removing/adding associations (after selecting a different device and then reselecting the one that was modified)…
The Thing.json has these (is this right or should they be node_1_0?)…
"group_1": [
"node_1"
],
And log has these, but this looks to be after starting the binding, not after reassociating…
zwave.log:2017-12-30 15:13:42.022 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Update ASSOCIATION group_ZWaveAssociationGroup [index=1, name=null, profile1=null, profile2=null, associations=[node_1]]: Adding node_1_null
Side issue, the log also has these… some for nodes that exist, some for nodes that DON’T exist, and some for nodes that CAN’T exist! The raw event looks right (it has these nodes in them), but the next events received look to have the same data, so maybe bad data/interference/etc., or bug in firmware? This is on a brand new HUSBZB-1 that I migrated to (from stick backup). Other stick had same. Curious what you think. I will open an issue if this could be a problem with the binding or if you’d like to look deeper.
zwave.log.1:2017-12-30 14:22:40.281 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 182: Not initialized (ie node unknown), ignoring message.
zwave.log.1:2017-12-30 10:25:42.978 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 248: Not initialized (ie node unknown), ignoring message.
zwave.log.1:2017-12-30 11:08:52.038 [WARN ] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 250: Not initialized (ie node unknown), ignoring message.
Hard to say - both are possible depending on the device.
This means that the controller recieved messages for these devices, but the controller did not report them during the initialisation. Clearly given the node numbers, something isn’t right - can you get a log please?
I’ve not seen this before - it likely means corrupt data being received I guess. I’ve also not changed any code around this, but feel free to provide a log and open an issue and I’ll have a quick look at least…
Previously, the association never seemed to actually be sent to the device. I am now seeing it go through, with a response back. So, other than the UI looking funny, it looks like we can set associations again!
2017-12-30 16:48:48.371 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Configuration update received
2017-12-30 16:48:48.373 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Configuration update group_1 to [node_1_1]
2017-12-30 16:48:48.374 [DEBUG] [protocol.commandclass.ZWaveAssociationCommandClass] - NODE 16: Creating new message for application command ASSOCIATIONCMD_SET
2017-12-30 16:48:48.375 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: Encapsulating message, endpoint 0
2017-12-30 16:48:48.375 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: SECURITY not supported
2017-12-30 16:48:48.376 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: Command Class COMMAND_CLASS_ASSOCIATION is NOT required to be secured
2017-12-30 16:48:48.376 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue
2017-12-30 16:48:48.377 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Added to queue - size 0
2017-12-30 16:48:48.396 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: listening == true, frequentlyListening == false, awake == false
2017-12-30 16:48:48.397 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 16: Sending REQUEST Message = 01 0B 00 13 10 04 85 01 01 01 25 52 00
2017-12-30 16:48:48.402 [DEBUG] [protocol.commandclass.ZWaveAssociationCommandClass] - NODE 16: Creating new message for application command ASSOCIATIONCMD_GET group 1
2017-12-30 16:48:48.403 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: Encapsulating message, endpoint 0
2017-12-30 16:48:48.403 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: SECURITY not supported
2017-12-30 16:48:48.403 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: Command Class COMMAND_CLASS_ASSOCIATION is NOT required to be secured
2017-12-30 16:48:48.403 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Adding to device queue
2017-12-30 16:48:48.403 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Added to queue - size 0
2017-12-30 16:48:48.406 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 16: sentData successfully placed on stack.
2017-12-30 16:48:48.407 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: TID 4281: Transaction not completed
2017-12-30 16:48:48.428 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 16: SendData Request. CallBack ID = 82, Status = Transmission complete and ACK received(0)
2017-12-30 16:48:48.428 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: resetResendCount initComplete=true isDead=false
2017-12-30 16:48:48.429 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Response processed after 28ms
2017-12-30 16:48:48.429 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: TID 4281: Transaction completed
2017-12-30 16:48:48.429 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: notifyTransactionResponse TID:4281 DONE
2017-12-30 16:48:48.430 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-12-30 16:48:48.438 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: listening == true, frequentlyListening == false, awake == false
2017-12-30 16:48:48.439 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - NODE 16: Sending REQUEST Message = 01 0A 00 13 10 03 85 02 01 25 53 05
2017-12-30 16:48:48.451 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 16: sentData successfully placed on stack.
2017-12-30 16:48:48.452 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: TID 4282: Transaction not completed
2017-12-30 16:48:48.466 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 16: SendData Request. CallBack ID = 83, Status = Transmission complete and ACK received(0)
2017-12-30 16:48:48.466 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: resetResendCount initComplete=true isDead=false
2017-12-30 16:48:48.466 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Response processed after 23ms
2017-12-30 16:48:48.466 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: TID 4282: Transaction completed
2017-12-30 16:48:48.466 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: notifyTransactionResponse TID:4282 DONE
2017-12-30 16:48:48.466 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2017-12-30 16:48:48.541 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Application Command Request (ALIVE:DONE)
2017-12-30 16:48:48.541 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: resetResendCount initComplete=true isDead=false
2017-12-30 16:48:48.541 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: Incoming command class COMMAND_CLASS_ASSOCIATION, endpoint 0
2017-12-30 16:48:48.541 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 16: SECURITY not supported
2017-12-30 16:48:48.541 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 16: Received COMMAND_CLASS_ASSOCIATION V1 ASSOCIATIONCMD_REPORT
2017-12-30 16:48:48.541 [DEBUG] [protocol.commandclass.ZWaveAssociationCommandClass] - NODE 16: association group 1 has max associations 232
2017-12-30 16:48:48.541 [DEBUG] [protocol.commandclass.ZWaveAssociationCommandClass] - NODE 16: association group 1 includes the following nodes:
2017-12-30 16:48:48.542 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Got an event from Z-Wave network: ZWaveAssociationEvent
2017-12-30 16:48:48.542 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_ASSOCIATION, value = 0
2017-12-30 16:48:48.542 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Update ASSOCIATION group_1
2017-12-30 16:48:48.542 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Update ASSOCIATION group_1: Adding node_1
2017-12-30 16:48:48.542 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Update ASSOCIATION group_1: 1 members
2017-12-30 16:48:48.542 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 16: Config updated
2017-12-30 16:48:48.600 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Commands processed 1.
2017-12-30 16:48:48.601 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 16: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@5ddf3d50.This is just a log error - I’ll fix that shortly.
Good - at least that seems consistent with my testing (although I didn’t notice the UI issue - this might depend on the device type).
Hi - would you mind sending me a screencap of your configuration parameters and association groups? If it’s working for you it really should be working for me…
When did you update? Running the dev snapshot build I installed yesterday morning, I’m still not seeing them set. (I’ve never actually seen them set, in the last few weeks I’ve been struggling to get the Zwave plugin working – it turns out like 80% of the problems I’ve been having is that associations weren’t working!)
The last update was yesterday afternoon (UK time).
Awesome, I’ll have to find some cycles today to try updating.
If the association issue is fixed, that ought to get me into a usable state with it. (I still haven’t managed to get secure inclusion working, but screwing with it was moot if I couldn’t get anything working.)
the weird thing is, in UI association groups are still showing as empty.
