Zwave/Habmin - Association Groups not stored anymore (since zwave update)

chris · October 3, 2018, 8:36pm

This will not be related to associations then. Associations are used for the device to report back to the controller if its state changes and it will not impact the sending of commands TO the node.

chris · October 3, 2018, 8:51pm

Please can you provide the file just zipped - not 7zip’ed. I don’t have any software to extract the .7 file.

norbert_jordan · October 3, 2018, 9:00pm

hm…its simply zipped with winzip not 7-zip. Guess you know that logs are rotated. So this is a simple txt file in the zip which is called openhab.log.7 like openhab.log.6 or openhab.log.5…can you please try. or remove the .7 so its only called openhab.log. should work hopefully.

Sure i know that the association group problem is a problem related to call back from the node to the controller, this should not be related (at least from my idea of zwave systems)…

many thanks.

chris · October 3, 2018, 9:04pm

Sorry - I thought this was 7-zipped…

The log shows that all messages to this node are timing out. As above, this is not related to association groups.

norbert_jordan · October 3, 2018, 9:07pm

hm, but how can this node than be online all day long ?

chris · October 3, 2018, 9:08pm

There are some messages received so it will be online at least some of the time.

norbert_jordan · October 3, 2018, 9:11pm

hm…for this node it may be comprehensible as it is rather far from the controller (next house)…so maybe this is an/the issue for this node. However i have another node that does not listen to rule based triggers since major update. Will try to catch such situation and kindly ask you to check again. For this one the distance is about 3 meters from the controller…so different kind of story. Thanks for now for checking…

norbert_jordan · October 4, 2018, 3:19pm

@chris …@old firmware v1.1 … is there already something new in the recent snapshot builds? I now tried several times…set association group, listed pending, if i reboot again the field is empty and the nodes to not provide updates to e.g. actual power values.

Kind Regards, Norbert

chris · October 4, 2018, 3:50pm

Please provide a log and I will have a look at what is happening. At the moment, I don’t know what your problem is and I don’t think the log you provided shows you setting the associations? If so, please advise the node number so I can check what is happening.

norbert_jordan · October 4, 2018, 7:56pm

ah OK. so you need input from myself. i thought that you see i have a FW1.1 and this is not covered correctly in the database and you would work on something…

@chris so what do you need in terms of logs…a situation where i try to change association groups via habmin? Regards

chris · October 7, 2018, 4:34pm

Yes, a log showing you setting the associations being set through HABmin would be useful - thanks.

Andrew_Pawelski · December 14, 2018, 8:33pm

Im getting this as well on previously working things.
I now have
a switch that doesnt respond physically
3 switches - different makes and models tjhat cant set the AG. It does sme as here - sets it, stays pending, then is there for a while in UI bu later its gone again.

Is there a way to log a specific device to its own log file? Ive tried putting the binding in debug for logging (to a a seperate file) but the log is still very busy with all my devices

Running on snapshot 1458

Andrew_Pawelski · December 14, 2018, 8:44pm

OK I think I captured during association…?

E 47: Sending REQUEST Message = 01 0A 00 13 2F 03 85 02 02 25 93 F9 
15-Dec-2018 07:08:47.948 [DEBUG] [g.openhab.binding.zwave.handler.ZWaveSerialHandler] - Message SENT
15-Dec-2018 07:08:47.948 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 27772: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 147
15-Dec-2018 07:08:47.949 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
15-Dec-2018 07:08:47.949 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
15-Dec-2018 07:08:47.949 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
15-Dec-2018 07:08:47.950 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 27772: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 147
15-Dec-2018 07:08:47.950 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg: ACK
15-Dec-2018 07:08:47.950 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
15-Dec-2018 07:08:47.950 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
15-Dec-2018 07:08:47.956 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
15-Dec-2018 07:08:47.956 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
15-Dec-2018 07:08:47.956 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
15-Dec-2018 07:08:47.956 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 27772: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 147
15-Dec-2018 07:08:47.956 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
15-Dec-2018 07:08:47.956 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 27772: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 147
15-Dec-2018 07:08:47.956 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
15-Dec-2018 07:08:47.956 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 47: sentData successfully placed on stack.
15-Dec-2018 07:08:47.956 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - TID 27772: Advanced to WAIT_REQUEST
15-Dec-2018 07:08:47.956 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 47: TID 27772: Transaction not completed
15-Dec-2018 07:08:47.956 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
15-Dec-2018 07:08:47.956 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
15-Dec-2018 07:08:47.976 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 93 00 00 03 7B 
15-Dec-2018 07:08:47.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=147, payload=93 00 00 03 
15-Dec-2018 07:08:47.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=147, payload=93 00 00 03 
15-Dec-2018 07:08:47.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction TID 27772: [WAIT_REQUEST] priority=Config, requiresResponse=true, callback: 147
15-Dec-2018 07:08:47.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
15-Dec-2018 07:08:47.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Last transaction: TID 27772: [WAIT_REQUEST] priority=Config, requiresResponse=true, callback: 147
15-Dec-2018 07:08:47.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Checking TID 27772: (Callback 147)
15-Dec-2018 07:08:47.977 [DEBUG] [ernal.protocol.serialmessage.ZWaveCommandProcessor] - Callback match!
15-Dec-2018 07:08:47.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Correlated to TID 27772: callback 147
15-Dec-2018 07:08:47.977 [DEBUG] [ab.binding.zwave.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=147, payload=93 00 00 03 
15-Dec-2018 07:08:47.977 [DEBUG] [ternal.protocol.serialmessage.SendDataMessageClass] - NODE 47: SendData Request. CallBack ID = 147, Status = Transmission complete and ACK received(0)
15-Dec-2018 07:08:47.977 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 47: resetResendCount initComplete=true isDead=false
15-Dec-2018 07:08:47.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - TID 27772: Advanced to WAIT_DATA
15-Dec-2018 07:08:47.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 47: TID 27772: Transaction not completed
15-Dec-2018 07:08:47.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
15-Dec-2018 07:08:47.977 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
15-Dec-2018 07:08:47.987 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0C 00 04 00 2F 06 85 03 02 01 00 01 5A 
15-Dec-2018 07:08:47.987 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=47, callback=0, payload=00 2F 06 85 03 02 01 00 01 
15-Dec-2018 07:08:47.987 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=47, callback=0, payload=00 2F 06 85 03 02 01 00 01 
15-Dec-2018 07:08:47.987 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null
15-Dec-2018 07:08:47.987 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 47: Application Command Request (ALIVE:DONE)
15-Dec-2018 07:08:47.987 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 47: resetResendCount initComplete=true isDead=false
15-Dec-2018 07:08:47.987 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 47: Incoming command class COMMAND_CLASS_ASSOCIATION, endpoint 0
15-Dec-2018 07:08:47.987 [DEBUG] [.openhab.binding.zwave.internal.protocol.ZWaveNode] - NODE 47: SECURITY not supported
15-Dec-2018 07:08:47.987 [DEBUG] [e.internal.protocol.commandclass.ZWaveCommandClass] - NODE 47: Received COMMAND_CLASS_ASSOCIATION V2 ASSOCIATIONCMD_REPORT
15-Dec-2018 07:08:47.987 [DEBUG] [protocol.commandclass.ZWaveAssociationCommandClass] - NODE 47: association group 2 has max associations 1
15-Dec-2018 07:08:47.988 [DEBUG] [protocol.commandclass.ZWaveAssociationCommandClass] - NODE 47: association group 2 includes the following nodes:
15-Dec-2018 07:08:47.988 [DEBUG] [protocol.commandclass.ZWaveAssociationCommandClass] - Node 1
15-Dec-2018 07:08:47.988 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 47: Got an event from Z-Wave network: ZWaveAssociationEvent
15-Dec-2018 07:08:47.988 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 47: Got a value event from Z-Wave network, endpoint = 0, command class = COMMAND_CLASS_ASSOCIATION, value = 0
15-Dec-2018 07:08:47.988 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 47: Commands processed 1.
15-Dec-2018 07:08:47.988 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 47: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@7d0867fc.
15-Dec-2018 07:08:47.988 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 47: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@7d0867fc.
15-Dec-2018 07:08:47.988 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - NODE 47: notifyTransactionResponse TID:27772 DONE
15-Dec-2018 07:08:47.988 [DEBUG] [rg.openhab.binding.zwave.handler.ZWaveThingHandler] - NODE 47: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
15-Dec-2018 07:08:47.989 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
15-Dec-2018 07:08:47.989 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
15-Dec-2018 07:08:47.989 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
15-Dec-2018 07:08:47.989 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
15-Dec-2018 07:09:24.508 [DEBUG] [wave.handler.ZWaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 0F 0A 60 0D 01 01 31 05 04 22 00 00 91 
15-Dec-2018 07:09:24.508 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 0A 60 0D 01 01 31 05 04 22 00 00 
15-Dec-2018 07:09:24.509 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=15, callback=0, payload=00 0F 0A 60 0D 01 01 31 05 04 22 00 00 
15-Dec-2018 07:09:24.509 [DEBUG] [ng.zwave.internal.protocol.ZWaveTransactionManager] - lastTransaction null

5iver · December 14, 2018, 8:44pm

I think that is possible, but try just tailing the log file, grepping for the node or nodes that you want…

tail -F -n1000 /opt/openhab2/userdata/logs/zwave/zwave.log | egrep "NODE 183:|NODE 232:"

Just keep in mind that this does not have all the raw goodies for deeper analysis, so find the time bock events that you want to investigate further, then go to the file and pull out the section you need.

Andrew_Pawelski · December 14, 2018, 8:46pm

Thanks - I was heading down a filter of the log or something similar but looking at the capture I have it may not provide all the info as not all the logging is with NODEx in each line.

Andrew_Pawelski · December 27, 2018, 12:52pm

did this help with helping troubleshoot?

chris · December 27, 2018, 3:04pm

The log just shows the reading of the association group - it’s not really showing any sort of issue.

Also, please don’t filter logs. You won’t be able to create a separate log per device (at least not one that is of any use to me ) since some logged data is not tagged with the node number as it is not known.

My guess is that the problem is that the UIs are sending commands that remove associations due to bugs in both PaperUI and HABmin. I have a PR ready for testing that will prevent removing associations if they are required by the system, so I hope that this will help solve this.

Andrew_Pawelski · December 30, 2018, 12:14pm

Sounds good happy to test and report back when its ready

chris · December 30, 2018, 7:38pm

Thanks - I’ll merge this soon. It has 2 fixes in it - one to force associations (ie to stop people removing them, or stop the UI screwing it up), and secondly I find that some UI somewhere can reformat the association arrays into strings, which then are not handled properly so I’ve put in a fix for that as well (ok, it’s a kludge as it should be fixed in ESH or the UI).

Andrew_Pawelski · January 2, 2019, 5:46am

Ok that is making the AG stick - didn’t solve my root cause which I was really hoping but I’ve created a different post about that