Zwave reconfigure association failed while working before

lsiepel · July 19, 2019, 6:42pm

Some time ago i was able to associate an Fibaro FGD212 S2 button (assocation group 4) to several other lights controlled by three other FGD212’s (endpoint 1) and two AN157 plugs (single endpoint devices)

I used this setup for over a year; when the S2 button is pressed , all associated lights go on/off as expected.

Last week, i changed the setup and removed all the devices from the association group. The lights no longer respond to the S2 button, so far so good. Now i add two FGD212’s and both AN157’s i waited a while and pressed the S2 button. Both FGD212’s work as expected, but the AN157 don’t respond at all.

What could be wrong?
Nothing showing up in the log (default log level) around the time i add or remove the devices from the association group.

I used Habmin to manage the association group, build 1641.

I just tried to remove all groups and add only one AN157, same problem it doesn’t respond. While it did work before and the AN157 responds to website on/off togle so it can’t be a hardware issue.

chris · July 19, 2019, 7:40pm

You should enable DEBUG logging to see what is happening.

lsiepel · July 19, 2019, 8:03pm

Changed log level, output below. Node 12 (FGD212) S2/group 4 controls the Node 26 (AN157). Because of transparancy, i didnt add/remove the other devices. If i interpreted the log, it succesfully removed the node and succesfully add the node after it failed at the first add attempt.

If i press the button nothing is happing to the AN157, i stopped the debug before i did. Does that command/response get into the log at all? Anyway if needed i can add it.

2019-07-19 21:44:42.260 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update received
2019-07-19 21:44:42.262 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update set group_4 to [] (EmptyList)
2019-07-19 21:44:42.263 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Association 4 consolidated to []
2019-07-19 21:44:42.264 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Current members before update ZWaveAssociationGroup [index=4, name=On/Off(S2), profile1=32, profile2=2, associations=[node_26_0]]
2019-07-19 21:44:42.265 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Members after config update ZWaveAssociationGroup [index=4, name=null, profile1=null, profile2=null, associations=[]]
2019-07-19 21:44:42.266 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller is master - forcing associations
2019-07-19 21:44:42.268 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Members after controller update ZWaveAssociationGroup [index=4, name=null, profile1=null, profile2=null, associations=[]]
2019-07-19 21:44:42.269 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Association group 4 contains no members. Clearing.
2019-07-19 21:44:42.270 [DEBUG] [ss.ZWaveMultiAssociationCommandClass] - NODE 12: Creating new message for command MULTI_ASSOCIATIONCMD_REMOVE node all, endpoint all, group 4
2019-07-19 21:44:42.270 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION
2019-07-19 21:44:42.271 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION is NOT required to be secured
2019-07-19 21:44:42.272 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue
2019-07-19 21:44:42.273 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 306 to queue - size 17
2019-07-19 21:44:42.274 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-19 21:44:42.275 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0C 03 8E 04 04 25 E6 A4 
2019-07-19 21:44:42.276 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 0A 00 13 0C 03 8E 04 04 25 E6 A4 
2019-07-19 21:44:42.277 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-19 21:44:42.278 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-07-19 21:44:42.278 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 306: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 230
2019-07-19 21:44:42.279 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 21:44:42.279 [DEBUG] [ss.ZWaveMultiAssociationCommandClass] - NODE 12: Creating new message for command MULTI_ASSOCIATIONCMD_GET group 4
2019-07-19 21:44:42.279 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 21:44:42.280 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 306: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 230
2019-07-19 21:44:42.280 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION
2019-07-19 21:44:42.280 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-07-19 21:44:42.281 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 21:44:42.281 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION is NOT required to be secured
2019-07-19 21:44:42.281 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 21:44:42.282 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue
2019-07-19 21:44:42.283 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 307 to queue - size 17
2019-07-19 21:44:42.284 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 21:44:42.285 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-07-19 21:44:42.285 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-07-19 21:44:42.286 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-07-19 21:44:42.287 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 306: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 230
2019-07-19 21:44:42.287 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-07-19 21:44:42.287 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 306: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 230
2019-07-19 21:44:42.288 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-07-19 21:44:42.289 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: sentData successfully placed on stack.
2019-07-19 21:44:42.289 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 306: Advanced to WAIT_REQUEST
2019-07-19 21:44:42.290 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 306: Transaction not completed
2019-07-19 21:44:42.290 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 21:44:42.290 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 21:44:42.328 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E6 00 00 05 08 
2019-07-19 21:44:42.329 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=230, payload=E6 00 00 05 
2019-07-19 21:44:42.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=230, payload=E6 00 00 05 
2019-07-19 21:44:42.330 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 306: [WAIT_REQUEST] priority=Config, requiresResponse=true, callback: 230
2019-07-19 21:44:42.331 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-07-19 21:44:42.331 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 306: [WAIT_REQUEST] priority=Config, requiresResponse=true, callback: 230
2019-07-19 21:44:42.332 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 306: (Callback 230)
2019-07-19 21:44:42.332 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-07-19 21:44:42.333 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 306: callback 230
2019-07-19 21:44:42.333 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=230, payload=E6 00 00 05 
2019-07-19 21:44:42.334 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: SendData Request. CallBack ID = 230, Status = Transmission complete and ACK received(0)
2019-07-19 21:44:42.335 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
2019-07-19 21:44:42.335 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 306: Transaction COMPLETED
2019-07-19 21:44:42.336 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Response processed after 58ms
2019-07-19 21:44:42.336 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 306: Transaction completed
2019-07-19 21:44:42.337 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: notifyTransactionResponse TID:306 DONE
2019-07-19 21:44:42.337 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-07-19 21:44:42.338 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 21:44:42.339 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-19 21:44:42.339 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0C 03 8E 02 04 25 E7 A3 
2019-07-19 21:44:42.340 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 0A 00 13 0C 03 8E 02 04 25 E7 A3 
2019-07-19 21:44:42.341 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-19 21:44:42.341 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 307: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 231
2019-07-19 21:44:42.342 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-07-19 21:44:42.342 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 21:44:42.343 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 21:44:42.344 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 307: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 231
2019-07-19 21:44:42.346 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-07-19 21:44:42.347 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 21:44:42.348 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 21:44:42.348 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-07-19 21:44:42.349 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-07-19 21:44:42.350 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-07-19 21:44:42.351 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 307: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 231
2019-07-19 21:44:42.352 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-07-19 21:44:42.353 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 307: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 231
2019-07-19 21:44:42.353 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-07-19 21:44:42.354 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: sentData successfully placed on stack.
2019-07-19 21:44:42.355 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 307: Advanced to WAIT_REQUEST
2019-07-19 21:44:42.356 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 307: Transaction not completed
2019-07-19 21:44:42.357 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 21:44:42.358 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 21:44:42.398 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E7 00 00 06 0A 
2019-07-19 21:44:42.399 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=231, payload=E7 00 00 06 
2019-07-19 21:44:42.400 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=231, payload=E7 00 00 06 
2019-07-19 21:44:42.401 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 307: [WAIT_REQUEST] priority=Config, requiresResponse=true, callback: 231
2019-07-19 21:44:42.402 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-07-19 21:44:42.403 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 307: [WAIT_REQUEST] priority=Config, requiresResponse=true, callback: 231
2019-07-19 21:44:42.403 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 307: (Callback 231)
2019-07-19 21:44:42.404 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-07-19 21:44:42.405 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 307: callback 231
2019-07-19 21:44:42.406 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=231, payload=E7 00 00 06 
2019-07-19 21:44:42.407 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: SendData Request. CallBack ID = 231, Status = Transmission complete and ACK received(0)
2019-07-19 21:44:42.408 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
2019-07-19 21:44:42.409 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 307: Advanced to WAIT_DATA
2019-07-19 21:44:42.410 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 307: Transaction not completed
2019-07-19 21:44:42.411 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 21:44:42.411 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 21:44:42.471 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0B 00 04 00 0C 05 8E 03 04 08 00 78 
2019-07-19 21:44:42.472 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 05 8E 03 04 08 00 
2019-07-19 21:44:42.473 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 05 8E 03 04 08 00 
2019-07-19 21:44:42.474 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-07-19 21:44:42.475 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:DONE)
2019-07-19 21:44:42.476 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
2019-07-19 21:44:42.477 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Incoming command class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION, endpoint 0
2019-07-19 21:44:42.478 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION
2019-07-19 21:44:42.479 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Received COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION V3 MULTI_ASSOCIATIONCMD_REPORT
2019-07-19 21:44:42.480 [DEBUG] [ss.ZWaveMultiAssociationCommandClass] - NODE 12: association group 4 has max associations 8
2019-07-19 21:44:42.481 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveAssociationEvent
2019-07-19 21:44:42.482 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_ASSOCIATION, value=0
2019-07-19 21:44:42.484 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Commands processed 1.
2019-07-19 21:44:42.484 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@717fe364.
2019-07-19 21:44:42.485 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@717fe364.
2019-07-19 21:44:42.486 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: notifyTransactionResponse TID:307 DONE
2019-07-19 21:44:42.487 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-07-19 21:44:42.488 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2019-07-19 21:44:42.489 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-07-19 21:44:42.490 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 21:44:42.491 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-19 21:44:56.016 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling...
2019-07-19 21:44:56.017 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 5: Polling deferred until initialisation complete
2019-07-19 21:45:18.076 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 10 00 04 00 28 0A 60 0D 01 01 31 05 04 22 00 00 B6 
2019-07-19 21:45:18.077 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=40, callback=0, payload=00 28 0A 60 0D 01 01 31 05 04 22 00 00 
2019-07-19 21:45:18.078 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=40, callback=0, payload=00 28 0A 60 0D 01 01 31 05 04 22 00 00 
2019-07-19 21:45:18.079 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-07-19 21:45:18.079 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 40: Application Command Request (ALIVE:DONE)
2019-07-19 21:45:18.080 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 40: resetResendCount initComplete=true isDead=false
2019-07-19 21:45:18.080 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 40: Decapsulating COMMAND_CLASS_MULTI_CHANNEL
2019-07-19 21:45:18.081 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 40: Incoming command class COMMAND_CLASS_SENSOR_MULTILEVEL, endpoint 1
2019-07-19 21:45:18.081 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 40: SECURITY NOT required on COMMAND_CLASS_SENSOR_MULTILEVEL
2019-07-19 21:45:18.082 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 40: Received COMMAND_CLASS_SENSOR_MULTILEVEL V4 SENSOR_MULTILEVEL_REPORT
2019-07-19 21:45:18.082 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 40: Sensor Type = Power(4), Scale = 0
2019-07-19 21:45:18.083 [DEBUG] [ss.ZWaveMultiLevelSensorCommandClass] - NODE 40: Sensor Value = 0E+1
2019-07-19 21:45:18.083 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Got an event from Z-Wave network: ZWaveMultiLevelSensorValueEvent
2019-07-19 21:45:18.084 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Got a value event from Z-Wave network, endpoint=1, command class=COMMAND_CLASS_SENSOR_MULTILEVEL, value=0E+1
2019-07-19 21:45:18.085 [DEBUG] [erter.ZWaveMultiLevelSensorConverter] - NODE 40: Sensor conversion not performed for POWER.
2019-07-19 21:45:18.086 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 40: Updating channel state zwave:device:512:node40:sensor_power1 to 0 [DecimalType]
2019-07-19 21:45:18.087 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 40: Commands processed 1.
2019-07-19 21:45:18.087 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 40: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@2593b413.
2019-07-19 21:45:18.088 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-07-19 21:45:18.088 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-07-19 21:45:18.089 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 21:45:18.089 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-19 21:45:30.622 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update received
2019-07-19 21:45:30.624 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Configuration update set group_4 to [node_26] (ArrayList)
2019-07-19 21:45:30.624 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Association 4 consolidated to [node_26]
2019-07-19 21:45:30.625 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Current members before update ZWaveAssociationGroup [index=4, name=On/Off(S2), profile1=32, profile2=2, associations=[]]
2019-07-19 21:45:30.626 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Members after config update ZWaveAssociationGroup [index=4, name=null, profile1=null, profile2=null, associations=[node_26]]
2019-07-19 21:45:30.626 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Controller is master - forcing associations
2019-07-19 21:45:30.628 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Members after controller update ZWaveAssociationGroup [index=4, name=null, profile1=null, profile2=null, associations=[node_26]]
2019-07-19 21:45:30.629 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Adding node_26 to association group 4
2019-07-19 21:45:30.629 [DEBUG] [ss.ZWaveMultiAssociationCommandClass] - NODE 12: Creating new message for command MULTI_ASSOCIATIONCMD_SET
2019-07-19 21:45:30.630 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION
2019-07-19 21:45:30.630 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION is NOT required to be secured
2019-07-19 21:45:30.631 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue
2019-07-19 21:45:30.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 308 to queue - size 17
2019-07-19 21:45:30.632 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-19 21:45:30.633 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0D 00 13 0C 06 8E 01 04 00 1A 00 25 E8 B7 
2019-07-19 21:45:30.634 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 0D 00 13 0C 06 8E 01 04 00 1A 00 25 E8 B7 
2019-07-19 21:45:30.635 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-19 21:45:30.636 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-07-19 21:45:30.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 308: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 232
2019-07-19 21:45:30.636 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 21:45:30.637 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 21:45:30.637 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 308: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 232
2019-07-19 21:45:30.637 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-07-19 21:45:30.638 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 21:45:30.638 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 21:45:30.638 [DEBUG] [ss.ZWaveMultiAssociationCommandClass] - NODE 12: Creating new message for command MULTI_ASSOCIATIONCMD_GET group 4
2019-07-19 21:45:30.639 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION
2019-07-19 21:45:30.639 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Command Class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION is NOT required to be secured
2019-07-19 21:45:30.640 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Adding to device queue
2019-07-19 21:45:30.641 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Added 309 to queue - size 17
2019-07-19 21:45:30.641 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 21:45:30.642 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-07-19 21:45:30.643 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-07-19 21:45:30.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-07-19 21:45:30.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 308: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 232
2019-07-19 21:45:30.644 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-07-19 21:45:30.645 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 308: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 232
2019-07-19 21:45:30.645 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-07-19 21:45:30.645 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: sentData successfully placed on stack.
2019-07-19 21:45:30.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 308: Advanced to WAIT_REQUEST
2019-07-19 21:45:30.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 308: Transaction not completed
2019-07-19 21:45:30.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 21:45:30.646 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 21:45:30.686 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E8 00 00 05 06 
2019-07-19 21:45:30.687 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=232, payload=E8 00 00 05 
2019-07-19 21:45:30.687 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=232, payload=E8 00 00 05 
2019-07-19 21:45:30.688 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 308: [WAIT_REQUEST] priority=Config, requiresResponse=true, callback: 232
2019-07-19 21:45:30.688 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-07-19 21:45:30.688 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 308: [WAIT_REQUEST] priority=Config, requiresResponse=true, callback: 232
2019-07-19 21:45:30.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 308: (Callback 232)
2019-07-19 21:45:30.689 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-07-19 21:45:30.689 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 308: callback 232
2019-07-19 21:45:30.689 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=232, payload=E8 00 00 05 
2019-07-19 21:45:30.690 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: SendData Request. CallBack ID = 232, Status = Transmission complete and ACK received(0)
2019-07-19 21:45:30.690 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
2019-07-19 21:45:30.690 [DEBUG] [e.internal.protocol.ZWaveTransaction] - TID 308: Transaction COMPLETED
2019-07-19 21:45:30.691 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Response processed after 55ms
2019-07-19 21:45:30.691 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 308: Transaction completed
2019-07-19 21:45:30.691 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: notifyTransactionResponse TID:308 DONE
2019-07-19 21:45:30.692 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-07-19 21:45:30.692 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 21:45:30.693 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.
2019-07-19 21:45:30.693 [DEBUG] [wave.internal.protocol.SerialMessage] - Assembled message buffer = 01 0A 00 13 0C 03 8E 02 04 25 E9 AD 
2019-07-19 21:45:30.694 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - NODE 12: Sending REQUEST Message = 01 0A 00 13 0C 03 8E 02 04 25 E9 AD 
2019-07-19 21:45:30.694 [DEBUG] [ing.zwave.handler.ZWaveSerialHandler] - Message SENT
2019-07-19 21:45:30.695 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage started: TID 309: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 233
2019-07-19 21:45:30.696 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 06
2019-07-19 21:45:30.696 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 21:45:30.700 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=null[0], type=ACK[2], dest=255, callback=0, payload=
2019-07-19 21:45:30.700 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 309: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 233
2019-07-19 21:45:30.701 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg: ACK
2019-07-19 21:45:30.702 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 04 01 13 01 E8 
2019-07-19 21:45:30.703 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-07-19 21:45:30.701 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 21:45:30.704 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 21:45:30.704 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-07-19 21:45:30.705 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 309: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 233
2019-07-19 21:45:30.705 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-07-19 21:45:30.706 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 309: [WAIT_RESPONSE] priority=Config, requiresResponse=true, callback: 233
2019-07-19 21:45:30.707 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Response[1], dest=255, callback=0, payload=01 
2019-07-19 21:45:30.707 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: sentData successfully placed on stack.
2019-07-19 21:45:30.708 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 309: Advanced to WAIT_REQUEST
2019-07-19 21:45:30.708 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 309: Transaction not completed
2019-07-19 21:45:30.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 21:45:30.709 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 21:45:30.758 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 07 00 13 E9 00 00 06 04 
2019-07-19 21:45:30.759 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=SendData[19], type=Request[0], dest=0, callback=233, payload=E9 00 00 06 
2019-07-19 21:45:30.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=SendData[19], type=Request[0], dest=0, callback=233, payload=E9 00 00 06 
2019-07-19 21:45:30.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction TID 309: [WAIT_REQUEST] priority=Config, requiresResponse=true, callback: 233
2019-07-19 21:45:30.760 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking outstanding transactions: 1
2019-07-19 21:45:30.761 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Last transaction: TID 309: [WAIT_REQUEST] priority=Config, requiresResponse=true, callback: 233
2019-07-19 21:45:30.761 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Checking TID 309: (Callback 233)
2019-07-19 21:45:30.761 [DEBUG] [.serialmessage.ZWaveCommandProcessor] - Callback match!
2019-07-19 21:45:30.761 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Correlated to TID 309: callback 233
2019-07-19 21:45:30.762 [DEBUG] [ve.internal.protocol.ZWaveController] - Incoming Message: Message: class=SendData[19], type=Request[0], dest=0, callback=233, payload=E9 00 00 06 
2019-07-19 21:45:30.762 [DEBUG] [l.serialmessage.SendDataMessageClass] - NODE 12: SendData Request. CallBack ID = 233, Status = Transmission complete and ACK received(0)
2019-07-19 21:45:30.763 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
2019-07-19 21:45:30.763 [DEBUG] [nal.protocol.ZWaveTransactionManager] - TID 309: Advanced to WAIT_DATA
2019-07-19 21:45:30.763 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: TID 309: Transaction not completed
2019-07-19 21:45:30.763 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 21:45:30.764 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 1 out at start. Holdoff false.
2019-07-19 21:45:30.832 [DEBUG] [WaveSerialHandler$ZWaveReceiveThread] - Receive Message = 01 0E 00 04 00 0C 08 8E 03 04 08 00 00 1A 00 6A 
2019-07-19 21:45:30.833 [DEBUG] [nal.protocol.ZWaveTransactionManager] - processReceiveMessage input 0<>128 : Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 08 8E 03 04 08 00 00 1A 00 
2019-07-19 21:45:30.834 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Received msg (0): Message: class=ApplicationCommandHandler[4], type=Request[0], dest=12, callback=0, payload=00 0C 08 8E 03 04 08 00 00 1A 00 
2019-07-19 21:45:30.834 [DEBUG] [nal.protocol.ZWaveTransactionManager] - lastTransaction null
2019-07-19 21:45:30.835 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Application Command Request (ALIVE:DONE)
2019-07-19 21:45:30.835 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: resetResendCount initComplete=true isDead=false
2019-07-19 21:45:30.835 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: Incoming command class COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION, endpoint 0
2019-07-19 21:45:30.836 [DEBUG] [ng.zwave.internal.protocol.ZWaveNode] - NODE 12: SECURITY NOT required on COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION
2019-07-19 21:45:30.836 [DEBUG] [tocol.commandclass.ZWaveCommandClass] - NODE 12: Received COMMAND_CLASS_MULTI_CHANNEL_ASSOCIATION V3 MULTI_ASSOCIATIONCMD_REPORT
2019-07-19 21:45:30.837 [DEBUG] [ss.ZWaveMultiAssociationCommandClass] - NODE 12: association group 4 has max associations 8
2019-07-19 21:45:30.837 [DEBUG] [ss.ZWaveMultiAssociationCommandClass] - NODE 12: Association group 4 includes the following nodes:
2019-07-19 21:45:30.838 [DEBUG] [ss.ZWaveMultiAssociationCommandClass] - NODE 12: Associated with Node 26 endpoint 0 in group
2019-07-19 21:45:30.838 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveAssociationEvent
2019-07-19 21:45:30.839 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got a value event from Z-Wave network, endpoint=0, command class=COMMAND_CLASS_ASSOCIATION, value=0
2019-07-19 21:45:30.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Commands processed 1.
2019-07-19 21:45:30.840 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Checking command org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@4827c957.
2019-07-19 21:45:30.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: Command verified org.openhab.binding.zwave.internal.protocol.ZWaveCommandClassPayload@4827c957.
2019-07-19 21:45:30.841 [DEBUG] [nal.protocol.ZWaveTransactionManager] - NODE 12: notifyTransactionResponse TID:309 DONE
2019-07-19 21:45:30.842 [DEBUG] [ding.zwave.handler.ZWaveThingHandler] - NODE 12: Got an event from Z-Wave network: ZWaveTransactionCompletedEvent
2019-07-19 21:45:30.842 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 1
2019-07-19 21:45:30.843 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction completed - outstandingTransactions 0
2019-07-19 21:45:30.843 [DEBUG] [nal.protocol.ZWaveTransactionManager] - ZWaveReceiveThread queue empty
2019-07-19 21:45:30.843 [DEBUG] [nal.protocol.ZWaveTransactionManager] - Transaction SendNextMessage 0 out at start. Holdoff false.

Bruce_Osborne · July 19, 2019, 8:08pm

In my understanding, the controller only controls Group 1.

I thought any other group numbers were used for direct device-to-device communication without going through the controller (or OH). Am I wrong in my understanding? (likely)

chris · July 20, 2019, 8:29am

It depends on the device. For ZWave Plus devices, this is generally correct - the lifeline group, which is required to be group 1 for ZW+ is the only association required for the controller, and the binding will automatically configure this group. Adding the controller to other groups can cause problems due to multiple messages being sent.

For older devices though all bets are off. For example, Fibaro used to use group 3 as the controller group, others used group 1, others had no controller group and you needed to select the messages you wanted. There was no recommendation in the standard and it was up to each manufacturer to implement their own thing.

chris · July 20, 2019, 8:38am

I don’t see any failure.

In the first command, you cleared the association group. The binding removes the association, then reads it back to double check -:

Then you set association group 4 to include node 26, this is set, then read back to confirm it is set.

This all looks fine to me.

You will not see anything in the log if node 12 is directly controlling node 26, so no need to look there. Unfortunately I can’t really comment on why the AN157 isn’t changing state - all I can really say is that the configuration looks correctly set based on what you have asked it to do.

lsiepel · July 20, 2019, 4:46pm

I thought some communication went wrong due to the log ‘transaction not complete’ line, but i was wrong. So all communication is ok. That is wat i expected before i posted the OP, because the binding didn’t throw an error a the default log level and permanent com errors should popup at that level.

Anyway, how to proceed? It clearly worked before, so the hardware / nodes can’t be the problem. Somehow i think it has to do with the multi endpoint goodies that was introduced to the binding not so long ago. Maybe i can install an old openhab version on a different machine and remove / add and see if there is any difference? Or would that be pointless?

chris · July 20, 2019, 4:49pm

Why?

Clearly the binding has nothing to do with this - the communication is between two other nodes that are not linked to openHAB.

The log clearly shows that OH has set the association configuration that you requested - either you requested the incorrect association, or there is another problem in the network where these two devices do not have a route between each-other.

Have you performed a heal?

lsiepel · July 20, 2019, 6:23pm

I’m pretty sure its something in the binding.

It worked before, and stopped working immediately after i removed and added the nodes from the associations group.
It happend to both AN157 plugs and tested it with two different FGD-212’s same result, no hardware issue.
No association settings where changed besides group 4, i select Node26 (no other endpoints available just one single option) what else could i possible do wrong when adding the node to the group?
The nodes have not recieved a firmware upgrade. (can only be performed from Fibaro hardware) so only thing changed between a year ago and now is openhab/binding/habmin
The nodes are 3 meters from eachother, can’t be a routing problem. They both react fast and without any problem to commands from other nodes.

So i installed 2.3.0 stable. That is as close as i could get to the 9th of september 2018 when the ‘dev branch’ was merged and all the new goodies where added.

And guess what… it worked again. I added the log file. Anything i should/could do to provide you with the necessairy data to fix this?
2_3_0.txt (10.9 KB)

After comparing again, i noticed the 2.5.0 way is adding an association to node26:0
version 2.3.0 lists node26 (without any addition) so is it the endpoint in the end )

chris · July 20, 2019, 7:12pm

Ok, the issue is that the binding used the multi-instance association. Unfortunately at the moment I can’t work on the ZWave binding due to problems with OH. Once that is fixed I will take a look, but this is not likely to be too soon I’m afraid.

lsiepel · July 20, 2019, 7:18pm

I’m following all the milestone 2 and bnd conversion stuff, the ESH openhab reintegration takes times. If everything is settled i will look into building a binding too, i have some idea’s, but i’m more a .NET /Microsoft developer, kind a steep learning curve.

Anyway i will file a github issue to the zwave repo with all the relevant logs etc. Thanks for looking into this.

Edit: The github issue: https://github.com/openhab/org.openhab.binding.zwave/issues/1205

dmit2k · July 31, 2019, 8:07am

Hi Chris!

First, a small off topic question - how can I get the same nice looking logs as on your screenshots? )

I have another problem which may be somehow related to multiple endpoints and Fibaro devices:

I have an FGRGBW RGBW Controller which I want to use as 4 single channels for controlling 4 led strips. According to documentation, FGRGBW RGBW Controller has 6 Endpoints where 4 last ones are for individual channels (R, G, B, W).

So I tried to assign different associations to each individual RGBW endpoint, but this does not work for me: either one controls ALL the channels at once. No way to control channels individually. Any ideas or suggestions?

I am on OH 2.4.0.1 (openhabian build)

Bruce_Osborne · July 31, 2019, 8:39am

Yo upload your log file to the log viewer to pretty it up.

https://www.cd-jackson.com/index.php/openhab/zwave-log-viewer

lsiepel · July 31, 2019, 1:25pm

I have the same FGRGBW and i can controll all channels independant. When i think about it, you would allways have to set the brightness channel to get power on one of the R/G/B/W channels. See the brightness as a master/absolute and the R/G/B/W as slave/relative channels.

Could you share your config in more detail?

dmit2k · July 31, 2019, 3:58pm

Yes, I can control R/G/B/W channels individually from OH2. I can also control them individually with attached physical I1-I4 inputs.

The problem is, when I try to associate a button or a scene controller z-wave device to specific R/G/B/W dimmer channel endpoint, ALL the RGBW channels are being changed at once. And this is not the problem with button / scene controllers - I tried to associate different initiating devices from different manufacturers including Fibaro Keyfob - all have the same behaviour.

So my guess is maybe OH incorrectly assigns the association and it goes to Endpoint 0 of RGBW controller, which controls all the channels at once? Not sure how can I check this though…

Or maybe I have set some wrong configuration settings for RGBW controller…

@lsiepel, would you please try to reproduce this bug with yours Fibaro RGBW controller and z-wave button / switch / dimmer association?

lsiepel · July 31, 2019, 5:11pm

The node from the OP is doing this: it’s a Fibaro FGD212 S2 button (assocation group 4) associated to the FGRGBW endpoint 1 (brightness). Note: i use openhab 2.5.0

Could you set the binding log level to debug, set the association and send command to the FGRGBW ?