Item/Node is not updated when a Default Response to a command is received

[flashbac]

Hi OH Community,

I’m running OH 3.1.0 and I have a custom ZigBee device that turns on an LED with the On/Off Cluster. For some reason, when I click on the OnOff switch item, OH sends the OffCommand and my ZigBee device replies with a Default Response with Status OK (0x00). However, in the logs, OH says that the Node is not updated. As a result, the item does not change to the Off state and the item always shows that it’s ON.

Because of that, when in the item configuration, the OH never sends an OnCommand using the Switch in the Analyze section.

Why is OH not updating the Item when it’s receiving an OK confirmation with the Default Response?

Thanks.

Logs below:

2021-07-13 13:42:58.040 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0013A20041A406E7: Command for channel zigbee:device:6f95a5142a:0013a20041a406e7:0013A20041A406E7_1_switch --> OFF [OnOffType]
2021-07-13 13:42:58.043 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0013A20041A406E7: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=0013A20041A406E7 queueTime=0, state=WAITING, sendCnt=0, command=OffCommand [On/Off: 0000/0 -> A909/1, cluster=0006, TID=--]]
2021-07-13 13:42:58.044 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
2021-07-13 13:42:58.046 [DEBUG] [transaction.ZigBeeTransactionManager] - A909/1: Sending ZigBeeTransaction [ieeeAddress=0013A20041A406E7 queueTime=4, state=WAITING, sendCnt=0, command=OffCommand [On/Off: 0000/0 -> A909/1, cluster=0006, TID=78]]
2021-07-13 13:42:58.047 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2021-07-13 13:42:58.050 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OffCommand [On/Off: 0000/0 -> A909/1, cluster=0006, TID=78]
2021-07-13 13:42:58.051 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=120, commandId=0]
2021-07-13 13:42:58.053 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=A909/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=7A, rssi=--, lqi=--, payload=01 78 00]
2021-07-13 13:42:58.055 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 0013A20041A406E7: Channel zigbee:device:6f95a5142a:0013a20041a406e7:0013A20041A406E7_1_switch waiting for response to OFF
2021-07-13 13:42:58.067 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=7F]
2021-07-13 13:42:58.089 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=A909, apsFrame=EmberApsFrame [profileId=0104, clusterId=0006, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=7F], messageTag=78, status=EMBER_SUCCESS, messageContents=]
2021-07-13 13:42:58.091 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=78 state=RX_ACK
2021-07-13 13:42:58.093 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=78, state=RX_ACK, outstanding=1
2021-07-13 13:42:58.095 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=A909, TID=78, event=RX_ACK, state=ACKED
2021-07-13 13:42:58.259 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingSenderEui64Handler [networkId=0, senderEui64=0013A20041A406E7]
2021-07-13 13:42:58.264 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0006, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_SOURCE_EUI64, EMBER_APS_OPTION_DESTINATION_EUI64], groupId=0, sequence=0C], lastHopLqi=255, lastHopRssi=-51, sender=A909, bindingIndex=255, addressIndex=255, messageContents=18 78 0B 00 00]
2021-07-13 13:42:58.266 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=A909/1, destinationAddress=0000/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=0C, rssi=-51, lqi=FF, payload=18 78 0B 00 00]
2021-07-13 13:42:58.269 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 0013A20041A406E7: Node update. NWK Address=A909
2021-07-13 13:42:58.271 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 0013A20041A406E7: Node A909 is not updated
2021-07-13 13:42:58.272 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=120, commandId=11]
2021-07-13 13:42:58.274 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: A909/1 -> 0000/1, cluster=0006, TID=78, commandIdentifier=0, statusCode=SUCCESS]
2021-07-13 13:42:58.275 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DefaultResponse [On/Off: A909/1 -> 0000/1, cluster=0006, TID=78, commandIdentifier=0, statusCode=SUCCESS] 
2021-07-13 13:42:58.277 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 0013A20041A406E7: Channel zigbee:device:6f95a5142a:0013a20041a406e7:0013A20041A406E7_1_switch received SUCCESS in response to OFF
2021-07-13 13:42:58.277 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=0013A20041A406E7 queueTime=235, state=COMPLETE, sendCnt=1, command=OffCommand [On/Off: 0000/0 -> A909/1, cluster=0006, TID=78]]
2021-07-13 13:42:58.279 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2021-07-13 13:42:58.281 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0013A20041A406E7: transactionComplete, state=COMPLETE, outstanding=0
2021-07-13 13:42:58.282 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2021-07-13 13:43:52.511 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0013A20041A406E7: Command for channel zigbee:device:6f95a5142a:0013a20041a406e7:0013A20041A406E7_1_switch --> OFF [OnOffType]
2021-07-13 13:43:52.514 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0013A20041A406E7: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=0013A20041A406E7 queueTime=0, state=WAITING, sendCnt=0, command=OffCommand [On/Off: 0000/0 -> A909/1, cluster=0006, TID=--]]
2021-07-13 13:43:52.515 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
2021-07-13 13:43:52.517 [DEBUG] [transaction.ZigBeeTransactionManager] - A909/1: Sending ZigBeeTransaction [ieeeAddress=0013A20041A406E7 queueTime=3, state=WAITING, sendCnt=0, command=OffCommand [On/Off: 0000/0 -> A909/1, cluster=0006, TID=79]]
2021-07-13 13:43:52.518 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2021-07-13 13:43:52.519 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OffCommand [On/Off: 0000/0 -> A909/1, cluster=0006, TID=79]
2021-07-13 13:43:52.520 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=121, commandId=0]
2021-07-13 13:43:52.522 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=A909/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=7B, rssi=--, lqi=--, payload=01 79 00]
2021-07-13 13:43:52.524 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 0013A20041A406E7: Channel zigbee:device:6f95a5142a:0013a20041a406e7:0013A20041A406E7_1_switch waiting for response to OFF
2021-07-13 13:43:52.536 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=80]
2021-07-13 13:43:52.559 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=A909, apsFrame=EmberApsFrame [profileId=0104, clusterId=0006, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=80], messageTag=79, status=EMBER_SUCCESS, messageContents=]
2021-07-13 13:43:52.561 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=79 state=RX_ACK
2021-07-13 13:43:52.563 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=79, state=RX_ACK, outstanding=1
2021-07-13 13:43:52.565 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=A909, TID=79, event=RX_ACK, state=ACKED
2021-07-13 13:43:52.728 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingSenderEui64Handler [networkId=0, senderEui64=0013A20041A406E7]
2021-07-13 13:43:52.733 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0006, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_SOURCE_EUI64, EMBER_APS_OPTION_DESTINATION_EUI64], groupId=0, sequence=0D], lastHopLqi=255, lastHopRssi=-55, sender=A909, bindingIndex=255, addressIndex=255, messageContents=18 79 0B 00 00]
2021-07-13 13:43:52.735 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=A909/1, destinationAddress=0000/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=0D, rssi=-55, lqi=FF, payload=18 79 0B 00 00]
2021-07-13 13:43:52.737 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 0013A20041A406E7: Node update. NWK Address=A909
2021-07-13 13:43:52.741 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 0013A20041A406E7: Node A909 is not updated
2021-07-13 13:43:52.744 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=121, commandId=11]
2021-07-13 13:43:52.747 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: A909/1 -> 0000/1, cluster=0006, TID=79, commandIdentifier=0, statusCode=SUCCESS]
2021-07-13 13:43:52.751 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DefaultResponse [On/Off: A909/1 -> 0000/1, cluster=0006, TID=79, commandIdentifier=0, statusCode=SUCCESS] 
2021-07-13 13:43:52.753 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 0013A20041A406E7: Channel zigbee:device:6f95a5142a:0013a20041a406e7:0013A20041A406E7_1_switch received SUCCESS in response to OFF
2021-07-13 13:43:52.753 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=0013A20041A406E7 queueTime=240, state=COMPLETE, sendCnt=1, command=OffCommand [On/Off: 0000/0 -> A909/1, cluster=0006, TID=79]]
2021-07-13 13:43:52.755 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2021-07-13 13:43:52.757 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0013A20041A406E7: transactionComplete, state=COMPLETE, outstanding=0
2021-07-13 13:43:52.758 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2021-07-13 13:47:01.742 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0013A20041A406E7: Command for channel zigbee:device:6f95a5142a:0013a20041a406e7:0013A20041A406E7_1_switch --> OFF [OnOffType]
2021-07-13 13:47:01.745 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0013A20041A406E7: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=0013A20041A406E7 queueTime=0, state=WAITING, sendCnt=0, command=OffCommand [On/Off: 0000/0 -> A909/1, cluster=0006, TID=--]]
2021-07-13 13:47:01.746 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
2021-07-13 13:47:01.748 [DEBUG] [transaction.ZigBeeTransactionManager] - A909/1: Sending ZigBeeTransaction [ieeeAddress=0013A20041A406E7 queueTime=3, state=WAITING, sendCnt=0, command=OffCommand [On/Off: 0000/0 -> A909/1, cluster=0006, TID=7A]]
2021-07-13 13:47:01.749 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2021-07-13 13:47:01.751 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OffCommand [On/Off: 0000/0 -> A909/1, cluster=0006, TID=7A]
2021-07-13 13:47:01.752 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=122, commandId=0]
2021-07-13 13:47:01.753 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=A909/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=7C, rssi=--, lqi=--, payload=01 7A 00]
2021-07-13 13:47:01.755 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 0013A20041A406E7: Channel zigbee:device:6f95a5142a:0013a20041a406e7:0013A20041A406E7_1_switch waiting for response to OFF
2021-07-13 13:47:01.768 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=81]
2021-07-13 13:47:01.791 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=A909, apsFrame=EmberApsFrame [profileId=0104, clusterId=0006, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=81], messageTag=7A, status=EMBER_SUCCESS, messageContents=]
2021-07-13 13:47:01.794 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=7A state=RX_ACK
2021-07-13 13:47:01.795 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=7A, state=RX_ACK, outstanding=1
2021-07-13 13:47:01.798 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=A909, TID=7A, event=RX_ACK, state=ACKED
2021-07-13 13:47:01.958 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingSenderEui64Handler [networkId=0, senderEui64=0013A20041A406E7]
2021-07-13 13:47:01.961 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0006, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_SOURCE_EUI64, EMBER_APS_OPTION_DESTINATION_EUI64], groupId=0, sequence=0E], lastHopLqi=255, lastHopRssi=-53, sender=A909, bindingIndex=255, addressIndex=255, messageContents=18 7A 0B 00 00]
2021-07-13 13:47:01.964 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=A909/1, destinationAddress=0000/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=0E, rssi=-53, lqi=FF, payload=18 7A 0B 00 00]
2021-07-13 13:47:01.968 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 0013A20041A406E7: Node update. NWK Address=A909
2021-07-13 13:47:01.970 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 0013A20041A406E7: Node A909 is not updated
2021-07-13 13:47:01.973 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=122, commandId=11]
2021-07-13 13:47:01.976 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: A909/1 -> 0000/1, cluster=0006, TID=7A, commandIdentifier=0, statusCode=SUCCESS]
2021-07-13 13:47:01.979 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DefaultResponse [On/Off: A909/1 -> 0000/1, cluster=0006, TID=7A, commandIdentifier=0, statusCode=SUCCESS] 
2021-07-13 13:47:01.980 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 0013A20041A406E7: Channel zigbee:device:6f95a5142a:0013a20041a406e7:0013A20041A406E7_1_switch received SUCCESS in response to OFF
2021-07-13 13:47:01.981 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=0013A20041A406E7 queueTime=236, state=COMPLETE, sendCnt=1, command=OffCommand [On/Off: 0000/0 -> A909/1, cluster=0006, TID=7A]]
2021-07-13 13:47:01.982 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2021-07-13 13:47:01.983 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0013A20041A406E7: transactionComplete, state=COMPLETE, outstanding=0
2021-07-13 13:47:01.984 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3
2021-07-13 13:47:49.055 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0013A20041A406E7: Command for channel zigbee:device:6f95a5142a:0013a20041a406e7:0013A20041A406E7_1_switch --> OFF [OnOffType]
2021-07-13 13:47:49.059 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0013A20041A406E7: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=0013A20041A406E7 queueTime=0, state=WAITING, sendCnt=0, command=OffCommand [On/Off: 0000/0 -> A909/1, cluster=0006, TID=--]]
2021-07-13 13:47:49.060 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=1, sleepy=0/3
2021-07-13 13:47:49.062 [DEBUG] [transaction.ZigBeeTransactionManager] - A909/1: Sending ZigBeeTransaction [ieeeAddress=0013A20041A406E7 queueTime=3, state=WAITING, sendCnt=0, command=OffCommand [On/Off: 0000/0 -> A909/1, cluster=0006, TID=7B]]
2021-07-13 13:47:49.063 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2021-07-13 13:47:49.064 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OffCommand [On/Off: 0000/0 -> A909/1, cluster=0006, TID=7B]
2021-07-13 13:47:49.065 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=123, commandId=0]
2021-07-13 13:47:49.067 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=A909/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=7D, rssi=--, lqi=--, payload=01 7B 00]
2021-07-13 13:47:49.069 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 0013A20041A406E7: Channel zigbee:device:6f95a5142a:0013a20041a406e7:0013A20041A406E7_1_switch waiting for response to OFF
2021-07-13 13:47:49.081 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=82]
2021-07-13 13:47:49.102 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=A909, apsFrame=EmberApsFrame [profileId=0104, clusterId=0006, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=82], messageTag=7B, status=EMBER_SUCCESS, messageContents=]
2021-07-13 13:47:49.104 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=7B state=RX_ACK
2021-07-13 13:47:49.105 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=7B, state=RX_ACK, outstanding=1
2021-07-13 13:47:49.107 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state changed: nwk=A909, TID=7B, event=RX_ACK, state=ACKED
2021-07-13 13:47:49.273 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingSenderEui64Handler [networkId=0, senderEui64=0013A20041A406E7]
2021-07-13 13:47:49.278 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0006, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_SOURCE_EUI64, EMBER_APS_OPTION_DESTINATION_EUI64], groupId=0, sequence=0F], lastHopLqi=255, lastHopRssi=-52, sender=A909, bindingIndex=255, addressIndex=255, messageContents=18 7B 0B 00 00]
2021-07-13 13:47:49.281 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=A909/1, destinationAddress=0000/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=0F, rssi=-52, lqi=FF, payload=18 7B 0B 00 00]
2021-07-13 13:47:49.283 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 0013A20041A406E7: Node update. NWK Address=A909
2021-07-13 13:47:49.285 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 0013A20041A406E7: Node A909 is not updated
2021-07-13 13:47:49.286 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=123, commandId=11]
2021-07-13 13:47:49.288 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: A909/1 -> 0000/1, cluster=0006, TID=7B, commandIdentifier=0, statusCode=SUCCESS]
2021-07-13 13:47:49.290 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DefaultResponse [On/Off: A909/1 -> 0000/1, cluster=0006, TID=7B, commandIdentifier=0, statusCode=SUCCESS] 
2021-07-13 13:47:49.292 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 0013A20041A406E7: Channel zigbee:device:6f95a5142a:0013a20041a406e7:0013A20041A406E7_1_switch received SUCCESS in response to OFF
2021-07-13 13:47:49.292 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=0013A20041A406E7 queueTime=233, state=COMPLETE, sendCnt=1, command=OffCommand [On/Off: 0000/0 -> A909/1, cluster=0006, TID=7B]]
2021-07-13 13:47:49.293 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2021-07-13 13:47:49.297 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0013A20041A406E7: transactionComplete, state=COMPLETE, outstanding=0
2021-07-13 13:47:49.299 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction Manager: Send Next transaction. outstandingTransactions=0, outstandingQueues=0, sleepy=0/3

[rossko57]

See

Conversion of dimmers into switches in zigbee binding

Can we just have an events.log of the issue? Some zigbee devices do not immediately report new status when commanded, and the zigbee binding vetoes the usual autoupdate effect that openHAB would normally apply. There is a workaround, apply autoupdate=“true” to your zigbee linked Item to void the veto.

[flashbac]

So either set autoupdate=“true” on the item, or configure the ZigBee device to send a report immediately after sending a successful Default Response?

I can’t find anywhere in the ZigBee spec where it says that a device SHALL send a report after receiving a command to the On/Off cluster. The only thing it says is:

3.8.2.7 Attribute Reporting
This cluster SHALL support attribute reporting using the Report Attributes command and according to the minimum and maximum reporting interval settings described in Chapter 2, Foundation. The following attribute SHALL be reported:
OnOff

[rossko57]

Well, whether it’s supposed to or not, your device doesn’t update promptly. There’s the workaround.

There’s a fairly extensive look at similar issues in this thread

Zigbee Bulbs update immediately to UNDEF, Items don't change from this

Ok, so the bulb should report back its state. When the command comes in from the UI, the UI doesn’t get updated at that point - we expect the device to send a report to say that it has changed state. This should normally come in within a second, and then the UI should be updated.

[flashbac]

So when the device registers, OH sends a Configure Reporting command with a Minimum Reporting Interval of 15mins, so my device is honoring that according to ZCL spec.

Also, according to ZCL spec, my device sends a Default Response Command with the correct status in response to a command.

So that begs the question, why OH is not honoring a acknowledgement that a command was SUCCESSFUL to update the item state?

This is making the ZigBee network twice as “chatty” by having to send two messages every time a command is successful: Default Response with Status Successful AND a Report Attribute Command.

[chris (Chris Jackson)]

@flashbac

So when the device registers, OH sends a Configure Reporting command with a Minimum Reporting Interval of 15mins, so my device is honoring that according to ZCL spec.

Not only this. The binding ALSO sets the configuration so that the device sends a report if the state changes. I would therefore argue your device is not respecting the spec by not sending the report.

This report is configured so that the binding is updated if the device is switched manually (or some other way outside of the binding), so is required to be configured this way.

However…

@flashbac

So that begs the question, why OH is not honoring a acknowledgement that a command was SUCCESSFUL to update the item state?

This is a fair question - I could probably change this, but for historical reasons this is just not the way it works. Commands were historically updated through the core rather than through the binding.

[flashbac]

Aaaah… Very well, I need to look into that. That also led me to find this regarding reports:

2.5.11.2.2 Changes to ‘Discrete’ At tributes
If the attribute has a ‘discrete’ data type, a report SHALL be generated when the attribute undergoes any change of value. Discrete types are general data types (which are often used as sets of bit fields), logical types, bitmap types, enumerations, strings, identifiers, IEEE address and security key (see Table 2-10).
Reporting is subject to the Minimum Reporting Interval for that attribute (see 2.5.7.1.5). After a report, no further reports are sent during this interval.

So since the OnOff attribute is a discrete data type (bool) my device is supposed to send a report any time it changes, so my device is not honoring neither OH’s Configure Reporting command NOR the ZCL.

I can fix that real quick.

Thank you Chris!

[flashbac]

OK, my device now sends a report every time the OnOff attribute changes ( or when any discrete reportable attribute changes). Everything is working perfect now.