[SOLVED] Items receive commands but stopped to update their states

[chris (Chris Jackson)]

Can you tell me the addresses of the devices that aren’t working? You blanked them out above so it’s not really easy for me to tell what they are

[guy-inkognito (Guy)]

Thanks @rossko57, you’re right

@chris, here we go:

Dimmer TestItem_Working {channel="zigbee:device:0137F59F:00124b00157d8e53:00124B00157D8E53_1_dimmer"}
Dimmer TestItem_NotWorking {channel="zigbee:device:0137F59F:0017880103d08243:0017880103D08243_11_dimmer"}

[rossko57]

Just as background to illuminate your results - for @chris too

I did some experiments with autoupdate …
Yes, the behaviour is different with allowing it to default per Item, and deliberately setting autoupdate="true". True forces autoupdate action, overriding any veto from the channel.

This is a revelation to me - an Item can effectively have one of three autoupdate policies - disabled (false), enabled (default), forced (true).

To complete the picture, only if Item autoupdate is enabled/default will it go on to look at channel policy (if any) and take that into into account.

[guy-inkognito (Guy)]

Hey there again!

Thanks for the additional info, @rossko57. After playing around a little bit more I’m under the impression, that forcing the autoupdate also seems to be a bad practice. I’ve experiences some inconsistencies with the group states, especially when mixing items with forced autoupdate and default autoupdate. However, it’s a bit difficult to really identify the cause, because I’m not sure if something very basic is messed up with my items though.

@chris, did you maybe had any chance to have a look into the logs?

[rossko57]

@guy-inkognito

I’ve experiences some inconsistencies with the group states

Don’t see any reason for that. Group states are derived from member states; it matters not what mechanism changes member states.

[guy-inkognito (Guy)]

@rossko57

Don’t see any reason for that. Group states are derived from member states; it matters not what mechanism changes member states.

I agree. That’s why I want to decouple this from the original issue, because I believe it’s caused by something unrelated.

[guy-inkognito (Guy)]

Hi @rossko57 and @chris,

I had the time to do a little more research here and I came up with another observation.

I can clearly differentiate the “working” devices from the “not working” devices by the fact that the latter ones fail to be initialized correctly.

So, when I, via Paper UI and the thing configuration page, trigger the “Initialize device” switch in the settings, I do get an error “Error opening device level controls” in the logs. This occurs for these things where the linked items do not update their states.

There is no such error in the logs for these things where the linked items do update their states.

Here you go with debug logs for the “not working” device initialization:

2020-07-26 15:28:46.199 [INFO ] [el.core.internal.ModelRepositoryImpl] - Refreshing model 'Investigation.items'

==> /var/log/openhab2/events.log <==

2020-07-26 15:29:52.905 [ome.event.ItemCommandEvent] - Item 'TestItem_NotWorking' received command 27

2020-07-26 15:29:58.909 [ome.event.ItemCommandEvent] - Item 'TestItem_NotWorking' received command 100

2020-07-26 15:30:08.698 [me.event.ThingUpdatedEvent] - Thing 'zigbee:device:0137F59F:0017880103d08243' has been updated.

==> /var/log/openhab2/openhab.log <==

2020-07-26 15:30:09.906 [ERROR] [converter.ZigBeeConverterSwitchLevel] - 0017880103D08243: Error opening device level controls

2020-07-26 15:30:09.909 [INFO ] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880103D08243: Channel zigbee:device:0137F59F:0017880103d08243:0017880103D08243_11_dimmer failed to initialise device

2020-07-26 15:30:36.128 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 00158D00015C55E3: Polling...

2020-07-26 15:30:41.954 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=38], lastHopLqi=255, lastHopRssi=-42, sender=65E6, bindingIndex=255, addressIndex=255, messageContents=01 DA 01 00 9D 11 01 11 12 14 03 17]

2020-07-26 15:30:41.961 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=65E6/1, destinationAddress=0000/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=38, rssi=-42, lqi=FF, payload=01 DA 01 00 9D 11 01 11 12 14 03 17]

2020-07-26 15:30:41.963 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=218, commandId=1]

2020-07-26 15:30:41.966 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: QueryNextImageCommand [Ota Upgrade: 65E6/1 -> 0000/1, cluster=0019, TID=DA, fieldControl=0, manufacturerCode=4509, imageType=4353, fileVersion=386077714, hardwareVersion=null]

2020-07-26 15:30:41.968 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: QueryNextImageCommand [Ota Upgrade: 65E6/1 -> 0000/1, cluster=0019, TID=DA, fieldControl=0, manufacturerCode=4509, imageType=4353, fileVersion=386077714, hardwareVersion=null] 

2020-07-26 15:30:41.972 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D000315530D: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D000315530D queueTime=0, state=WAITING, sendCnt=0, command=QueryNextImageResponse [Ota Upgrade: 0000/0 -> 65E6/1, cluster=0019, TID=DA, status=NO_IMAGE_AVAILABLE, manufacturerCode=4509, imageType=4353, fileVersion=386077714, imageSize=0]]

2020-07-26 15:30:41.975 [DEBUG] [transaction.ZigBeeTransactionManager] - 65E6/1: Sending ZigBeeTransaction [ieeeAddress=00158D000315530D queueTime=4, state=WAITING, sendCnt=0, command=QueryNextImageResponse [Ota Upgrade: 0000/0 -> 65E6/1, cluster=0019, TID=DA, status=NO_IMAGE_AVAILABLE, manufacturerCode=4509, imageType=4353, fileVersion=386077714, imageSize=0]]

2020-07-26 15:30:41.977 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-07-26 15:30:41.980 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: QueryNextImageResponse [Ota Upgrade: 0000/0 -> 65E6/1, cluster=0019, TID=DA, status=NO_IMAGE_AVAILABLE, manufacturerCode=4509, imageType=4353, fileVersion=386077714, imageSize=0]

2020-07-26 15:30:41.983 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=218, commandId=2]

2020-07-26 15:30:41.986 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=65E6/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=D0, rssi=--, lqi=--, payload=19 DA 02 98]

2020-07-26 15:30:42.000 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=12]

2020-07-26 15:30:42.049 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=65E6, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=12], messageTag=DA, status=EMBER_SUCCESS, messageContents=]

2020-07-26 15:30:42.051 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=DA state=RX_ACK

2020-07-26 15:30:42.053 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=DA, state=RX_ACK, outstanding=1

2020-07-26 15:30:42.055 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D000315530D queueTime=84, state=COMPLETE, sendCnt=1, command=QueryNextImageResponse [Ota Upgrade: 0000/0 -> 65E6/1, cluster=0019, TID=DA, status=NO_IMAGE_AVAILABLE, manufacturerCode=4509, imageType=4353, fileVersion=386077714, imageSize=0]]

2020-07-26 15:30:42.057 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-07-26 15:30:42.059 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D000315530D: transactionComplete COMPLETE 0

2020-07-26 15:30:42.061 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID DA -> RX_ACK == COMPLETE

2020-07-26 15:30:48.650 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=1F], lastHopLqi=255, lastHopRssi=-41, sender=D30F, bindingIndex=255, addressIndex=255, messageContents=01 1A 01 00 9D 11 01 11 12 14 03 17]

2020-07-26 15:30:48.653 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=D30F/1, destinationAddress=0000/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=1F, rssi=-41, lqi=FF, payload=01 1A 01 00 9D 11 01 11 12 14 03 17]

2020-07-26 15:30:48.655 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=26, commandId=1]

2020-07-26 15:30:48.657 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: QueryNextImageCommand [Ota Upgrade: D30F/1 -> 0000/1, cluster=0019, TID=1A, fieldControl=0, manufacturerCode=4509, imageType=4353, fileVersion=386077714, hardwareVersion=null]

2020-07-26 15:30:48.659 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: QueryNextImageCommand [Ota Upgrade: D30F/1 -> 0000/1, cluster=0019, TID=1A, fieldControl=0, manufacturerCode=4509, imageType=4353, fileVersion=386077714, hardwareVersion=null] 

2020-07-26 15:30:48.663 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00015C4E6C: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=00158D00015C4E6C queueTime=0, state=WAITING, sendCnt=0, command=QueryNextImageResponse [Ota Upgrade: 0000/0 -> D30F/1, cluster=0019, TID=1A, status=NO_IMAGE_AVAILABLE, manufacturerCode=4509, imageType=4353, fileVersion=386077714, imageSize=0]]

2020-07-26 15:30:48.666 [DEBUG] [transaction.ZigBeeTransactionManager] - D30F/1: Sending ZigBeeTransaction [ieeeAddress=00158D00015C4E6C queueTime=3, state=WAITING, sendCnt=0, command=QueryNextImageResponse [Ota Upgrade: 0000/0 -> D30F/1, cluster=0019, TID=1A, status=NO_IMAGE_AVAILABLE, manufacturerCode=4509, imageType=4353, fileVersion=386077714, imageSize=0]]

2020-07-26 15:30:48.668 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-07-26 15:30:48.671 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: QueryNextImageResponse [Ota Upgrade: 0000/0 -> D30F/1, cluster=0019, TID=1A, status=NO_IMAGE_AVAILABLE, manufacturerCode=4509, imageType=4353, fileVersion=386077714, imageSize=0]

2020-07-26 15:30:48.674 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=26, commandId=2]

2020-07-26 15:30:48.676 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=D30F/1, profile=0104, cluster=0019, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=D1, rssi=--, lqi=--, payload=19 1A 02 98]

2020-07-26 15:30:48.691 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=13]

2020-07-26 15:30:48.785 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteErrorHandler [networkId=0, status=EMBER_SOURCE_ROUTE_FAILURE, target=D30F]

2020-07-26 15:30:48.809 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=D30F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0019, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=13], messageTag=1A, status=EMBER_SUCCESS, messageContents=]

2020-07-26 15:30:48.811 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=1A state=RX_ACK

2020-07-26 15:30:48.813 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=1A, state=RX_ACK, outstanding=1

2020-07-26 15:30:48.816 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=00158D00015C4E6C queueTime=153, state=COMPLETE, sendCnt=1, command=QueryNextImageResponse [Ota Upgrade: 0000/0 -> D30F/1, cluster=0019, TID=1A, status=NO_IMAGE_AVAILABLE, manufacturerCode=4509, imageType=4353, fileVersion=386077714, imageSize=0]]

2020-07-26 15:30:48.818 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-07-26 15:30:48.820 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 00158D00015C4E6C: transactionComplete COMPLETE 0

2020-07-26 15:30:48.822 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 1A -> RX_ACK == COMPLETE

2020-07-26 15:30:56.455 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880103D08243: Configuration received: {zigbee_macaddress=0017880103D08243, zigbee_initialise_device=true}

2020-07-26 15:30:56.457 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880103D08243: Configuration update: Ignored zigbee_macaddress as no change

2020-07-26 15:30:56.459 [DEBUG] [e.internal.ZigBeeDeviceConfigHandler] - Configuration update: Ignored zigbee_macaddress as no change

2020-07-26 15:30:56.464 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880103D08243: Configuration updated: Reinitialise device

2020-07-26 15:30:56.466 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880103D08243: Initializing device

==> /var/log/openhab2/events.log <==

2020-07-26 15:30:56.467 [me.event.ThingUpdatedEvent] - Thing 'zigbee:device:0137F59F:0017880103d08243' has been updated.

==> /var/log/openhab2/openhab.log <==

2020-07-26 15:30:56.469 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880103D08243: Initializing channel zigbee:device:0137F59F:0017880103d08243:0017880103D08243_11_colortemperature with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterColorTemperature@bb857b

2020-07-26 15:30:56.472 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0017880103D08243: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> CB64/0, cluster=0021, TID=--, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]]

2020-07-26 15:30:56.475 [DEBUG] [transaction.ZigBeeTransactionManager] - CB64/0: Sending ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=3, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> CB64/0, cluster=0021, TID=6D, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]]

2020-07-26 15:30:56.476 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-07-26 15:30:56.479 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> CB64/0, cluster=0021, TID=6D, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]

2020-07-26 15:30:56.482 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=CB64/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=D2, rssi=--, lqi=--, payload=6D 43 82 D0 03 01 88 17 00 0B 00 03 03 46 F6 3A 0D 00 6F 0D 00 01]

2020-07-26 15:30:56.497 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=14]

2020-07-26 15:30:56.546 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=CB64, sourceEui=0017880103D08243, lastHopLqi=255, lastHopRssi=-41, relayList=F753]

2020-07-26 15:30:56.629 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=CB64, apsFrame=EmberApsFrame [profileId=0000, clusterId=0021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=14], messageTag=6D, status=EMBER_SUCCESS, messageContents=]

2020-07-26 15:30:56.630 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=6D state=RX_ACK

2020-07-26 15:30:56.631 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=6D, state=RX_ACK, outstanding=1

2020-07-26 15:30:56.632 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 6D -> RX_ACK == ACKED

2020-07-26 15:30:56.651 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=CB64, sourceEui=0017880103D08243, lastHopLqi=255, lastHopRssi=-42, relayList=F753]

2020-07-26 15:30:56.716 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=93], lastHopLqi=255, lastHopRssi=-41, sender=CB64, bindingIndex=255, addressIndex=255, messageContents=6D 00]

2020-07-26 15:30:56.717 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=CB64/0, destinationAddress=0000/0, profile=0000, cluster=8021, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=93, rssi=-41, lqi=FF, payload=6D 00]

2020-07-26 15:30:56.719 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [CB64/0 -> 0000/0, cluster=8021, TID=6D, status=SUCCESS]

2020-07-26 15:30:56.720 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [CB64/0 -> 0000/0, cluster=8021, TID=6D, status=SUCCESS] 

2020-07-26 15:30:56.722 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [CB64/0 -> 0000/0, cluster=8021, TID=6D, status=SUCCESS] ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=250, state=ACKED, sendCnt=1, command=BindRequest [0000/0 -> CB64/0, cluster=0021, TID=6D, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]]

2020-07-26 15:30:56.723 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=252, state=COMPLETE, sendCnt=1, command=BindRequest [0000/0 -> CB64/0, cluster=0021, TID=6D, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]]

2020-07-26 15:30:56.723 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0017880103D08243: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=0, state=WAITING, sendCnt=0, command=ConfigureReportingCommand [Color Control: 0000/0 -> CB64/11, cluster=0300, TID=--, records=[AttributeReportingConfigurationRecord [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=7, direction=0, minimumReportingInterval=1, maximumReportingInterval=7200, reportableChange=1]]]]

2020-07-26 15:30:56.725 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-07-26 15:30:56.725 [DEBUG] [transaction.ZigBeeTransactionManager] - CB64/11: Sending ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=2, state=WAITING, sendCnt=0, command=ConfigureReportingCommand [Color Control: 0000/0 -> CB64/11, cluster=0300, TID=6E, records=[AttributeReportingConfigurationRecord [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=7, direction=0, minimumReportingInterval=1, maximumReportingInterval=7200, reportableChange=1]]]]

2020-07-26 15:30:56.727 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-07-26 15:30:56.729 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ConfigureReportingCommand [Color Control: 0000/0 -> CB64/11, cluster=0300, TID=6E, records=[AttributeReportingConfigurationRecord [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=7, direction=0, minimumReportingInterval=1, maximumReportingInterval=7200, reportableChange=1]]]

2020-07-26 15:30:56.731 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=110, commandId=6]

2020-07-26 15:30:56.732 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=CB64/11, profile=0104, cluster=0300, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=D3, rssi=--, lqi=--, payload=00 6E 06 00 07 00 21 01 00 20 1C 01 00]

2020-07-26 15:30:56.735 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0017880103D08243: transactionComplete COMPLETE 1

2020-07-26 15:30:56.747 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=15]

2020-07-26 15:30:56.796 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=CB64, sourceEui=0017880103D08243, lastHopLqi=255, lastHopRssi=-42, relayList=F753]

2020-07-26 15:30:56.879 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=CB64, apsFrame=EmberApsFrame [profileId=0104, clusterId=0300, sourceEndpoint=1, destinationEndpoint=11, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=15], messageTag=6E, status=EMBER_SUCCESS, messageContents=]

2020-07-26 15:30:56.880 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=6E state=RX_ACK

2020-07-26 15:30:56.881 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=6E, state=RX_ACK, outstanding=1

2020-07-26 15:30:56.882 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 6E -> RX_ACK == ACKED

2020-07-26 15:30:56.901 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=CB64, sourceEui=0017880103D08243, lastHopLqi=255, lastHopRssi=-42, relayList=F753]

2020-07-26 15:30:56.969 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0300, sourceEndpoint=11, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=94], lastHopLqi=255, lastHopRssi=-41, sender=CB64, bindingIndex=255, addressIndex=255, messageContents=18 6E 0B 06 82]

2020-07-26 15:30:56.972 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=CB64/11, destinationAddress=0000/1, profile=0104, cluster=0300, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=94, rssi=-41, lqi=FF, payload=18 6E 0B 06 82]

2020-07-26 15:30:56.973 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=110, commandId=11]

2020-07-26 15:30:56.976 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [Color Control: CB64/11 -> 0000/1, cluster=0300, TID=6E, commandIdentifier=6, statusCode=UNSUP_GENERAL_COMMAND]

2020-07-26 15:30:56.978 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DefaultResponse [Color Control: CB64/11 -> 0000/1, cluster=0300, TID=6E, commandIdentifier=6, statusCode=UNSUP_GENERAL_COMMAND] 

2020-07-26 15:30:56.981 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DefaultResponse [Color Control: CB64/11 -> 0000/1, cluster=0300, TID=6E, commandIdentifier=6, statusCode=UNSUP_GENERAL_COMMAND] ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=257, state=ACKED, sendCnt=1, command=ConfigureReportingCommand [Color Control: 0000/0 -> CB64/11, cluster=0300, TID=6E, records=[AttributeReportingConfigurationRecord [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=7, direction=0, minimumReportingInterval=1, maximumReportingInterval=7200, reportableChange=1]]]]

2020-07-26 15:30:56.984 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=260, state=COMPLETE, sendCnt=1, command=ConfigureReportingCommand [Color Control: 0000/0 -> CB64/11, cluster=0300, TID=6E, records=[AttributeReportingConfigurationRecord [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=7, direction=0, minimumReportingInterval=1, maximumReportingInterval=7200, reportableChange=1]]]]

2020-07-26 15:30:56.984 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0017880103D08243: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=0, state=WAITING, sendCnt=0, command=ConfigureReportingCommand [Color Control: 0000/0 -> CB64/11, cluster=0300, TID=--, records=[AttributeReportingConfigurationRecord [attributeDataType=ENUMERATION_8_BIT, attributeIdentifier=8, direction=0, minimumReportingInterval=1, maximumReportingInterval=7200]]]]

2020-07-26 15:30:56.986 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-07-26 15:30:56.988 [DEBUG] [transaction.ZigBeeTransactionManager] - CB64/11: Sending ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=4, state=WAITING, sendCnt=0, command=ConfigureReportingCommand [Color Control: 0000/0 -> CB64/11, cluster=0300, TID=6F, records=[AttributeReportingConfigurationRecord [attributeDataType=ENUMERATION_8_BIT, attributeIdentifier=8, direction=0, minimumReportingInterval=1, maximumReportingInterval=7200]]]]

2020-07-26 15:30:56.991 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-07-26 15:30:56.994 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ConfigureReportingCommand [Color Control: 0000/0 -> CB64/11, cluster=0300, TID=6F, records=[AttributeReportingConfigurationRecord [attributeDataType=ENUMERATION_8_BIT, attributeIdentifier=8, direction=0, minimumReportingInterval=1, maximumReportingInterval=7200]]]

2020-07-26 15:30:56.997 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=111, commandId=6]

2020-07-26 15:30:57.001 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=CB64/11, profile=0104, cluster=0300, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=D4, rssi=--, lqi=--, payload=00 6F 06 00 08 00 30 01 00 20 1C]

2020-07-26 15:30:57.004 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0017880103D08243: transactionComplete COMPLETE 1

2020-07-26 15:30:57.015 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=16]

2020-07-26 15:30:57.069 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=CB64, sourceEui=0017880103D08243, lastHopLqi=255, lastHopRssi=-41, relayList=F753]

2020-07-26 15:30:57.149 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=CB64, apsFrame=EmberApsFrame [profileId=0104, clusterId=0300, sourceEndpoint=1, destinationEndpoint=11, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=16], messageTag=6F, status=EMBER_SUCCESS, messageContents=]

2020-07-26 15:30:57.151 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=6F state=RX_ACK

2020-07-26 15:30:57.153 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=6F, state=RX_ACK, outstanding=1

2020-07-26 15:30:57.156 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 6F -> RX_ACK == ACKED

2020-07-26 15:30:57.172 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=CB64, sourceEui=0017880103D08243, lastHopLqi=255, lastHopRssi=-41, relayList=F753]

2020-07-26 15:30:57.230 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0300, sourceEndpoint=11, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=95], lastHopLqi=255, lastHopRssi=-41, sender=CB64, bindingIndex=255, addressIndex=255, messageContents=18 6F 0B 06 82]

2020-07-26 15:30:57.232 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=CB64/11, destinationAddress=0000/1, profile=0104, cluster=0300, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=95, rssi=-41, lqi=FF, payload=18 6F 0B 06 82]

2020-07-26 15:30:57.235 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=111, commandId=11]

2020-07-26 15:30:57.237 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [Color Control: CB64/11 -> 0000/1, cluster=0300, TID=6F, commandIdentifier=6, statusCode=UNSUP_GENERAL_COMMAND]

2020-07-26 15:30:57.240 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DefaultResponse [Color Control: CB64/11 -> 0000/1, cluster=0300, TID=6F, commandIdentifier=6, statusCode=UNSUP_GENERAL_COMMAND] 

2020-07-26 15:30:57.242 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DefaultResponse [Color Control: CB64/11 -> 0000/1, cluster=0300, TID=6F, commandIdentifier=6, statusCode=UNSUP_GENERAL_COMMAND] ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=258, state=ACKED, sendCnt=1, command=ConfigureReportingCommand [Color Control: 0000/0 -> CB64/11, cluster=0300, TID=6F, records=[AttributeReportingConfigurationRecord [attributeDataType=ENUMERATION_8_BIT, attributeIdentifier=8, direction=0, minimumReportingInterval=1, maximumReportingInterval=7200]]]]

2020-07-26 15:30:57.245 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=262, state=COMPLETE, sendCnt=1, command=ConfigureReportingCommand [Color Control: 0000/0 -> CB64/11, cluster=0300, TID=6F, records=[AttributeReportingConfigurationRecord [attributeDataType=ENUMERATION_8_BIT, attributeIdentifier=8, direction=0, minimumReportingInterval=1, maximumReportingInterval=7200]]]]

2020-07-26 15:30:57.246 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880103D08243: Initializing channel zigbee:device:0137F59F:0017880103d08243:0017880103D08243_11_dimmer with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel@476977

2020-07-26 15:30:57.248 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-07-26 15:30:57.250 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0017880103D08243: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> CB64/0, cluster=0021, TID=--, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=8, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]]

2020-07-26 15:30:57.254 [DEBUG] [transaction.ZigBeeTransactionManager] - CB64/0: Sending ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=4, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> CB64/0, cluster=0021, TID=70, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=8, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]]

2020-07-26 15:30:57.257 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-07-26 15:30:57.260 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> CB64/0, cluster=0021, TID=70, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=8, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]

2020-07-26 15:30:57.263 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=CB64/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=D5, rssi=--, lqi=--, payload=70 43 82 D0 03 01 88 17 00 0B 08 00 03 46 F6 3A 0D 00 6F 0D 00 01]

2020-07-26 15:30:57.266 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0017880103D08243: transactionComplete COMPLETE 1

2020-07-26 15:30:57.281 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=17]

2020-07-26 15:30:57.328 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=CB64, sourceEui=0017880103D08243, lastHopLqi=255, lastHopRssi=-42, relayList=F753]

2020-07-26 15:30:57.395 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=CB64, apsFrame=EmberApsFrame [profileId=0000, clusterId=0021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=17], messageTag=70, status=EMBER_SUCCESS, messageContents=]

2020-07-26 15:30:57.397 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=70 state=RX_ACK

2020-07-26 15:30:57.399 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=70, state=RX_ACK, outstanding=1

2020-07-26 15:30:57.401 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 70 -> RX_ACK == ACKED

2020-07-26 15:30:57.422 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=CB64, sourceEui=0017880103D08243, lastHopLqi=255, lastHopRssi=-41, relayList=F753]

2020-07-26 15:30:57.489 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=96], lastHopLqi=255, lastHopRssi=-41, sender=CB64, bindingIndex=255, addressIndex=255, messageContents=70 8C]

2020-07-26 15:30:57.491 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=CB64/0, destinationAddress=0000/0, profile=0000, cluster=8021, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=96, rssi=-41, lqi=FF, payload=70 8C]

2020-07-26 15:30:57.493 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [CB64/0 -> 0000/0, cluster=8021, TID=70, status=TABLE_FULL]

2020-07-26 15:30:57.495 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [CB64/0 -> 0000/0, cluster=8021, TID=70, status=TABLE_FULL] 

2020-07-26 15:30:57.498 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [CB64/0 -> 0000/0, cluster=8021, TID=70, status=TABLE_FULL] ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=248, state=ACKED, sendCnt=1, command=BindRequest [0000/0 -> CB64/0, cluster=0021, TID=70, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=8, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]]

2020-07-26 15:30:57.501 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=251, state=COMPLETE, sendCnt=1, command=BindRequest [0000/0 -> CB64/0, cluster=0021, TID=70, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=8, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]]

2020-07-26 15:30:57.501 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 0017880103D08243: Failed to bind level control cluster

2020-07-26 15:30:57.503 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-07-26 15:30:57.504 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0017880103D08243: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> CB64/0, cluster=0021, TID=--, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=6, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]]

2020-07-26 15:30:57.509 [DEBUG] [transaction.ZigBeeTransactionManager] - CB64/0: Sending ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=5, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> CB64/0, cluster=0021, TID=71, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=6, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]]

2020-07-26 15:30:57.511 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-07-26 15:30:57.515 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> CB64/0, cluster=0021, TID=71, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=6, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]

2020-07-26 15:30:57.518 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=CB64/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=D6, rssi=--, lqi=--, payload=71 43 82 D0 03 01 88 17 00 0B 06 00 03 46 F6 3A 0D 00 6F 0D 00 01]

2020-07-26 15:30:57.521 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0017880103D08243: transactionComplete COMPLETE 1

2020-07-26 15:30:57.536 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=18]

2020-07-26 15:30:57.591 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=CB64, sourceEui=0017880103D08243, lastHopLqi=255, lastHopRssi=-42, relayList=F753]

2020-07-26 15:30:57.668 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=CB64, apsFrame=EmberApsFrame [profileId=0000, clusterId=0021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=18], messageTag=71, status=EMBER_SUCCESS, messageContents=]

2020-07-26 15:30:57.672 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=71 state=RX_ACK

2020-07-26 15:30:57.674 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=71, state=RX_ACK, outstanding=1

2020-07-26 15:30:57.676 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 71 -> RX_ACK == ACKED

2020-07-26 15:30:57.691 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=CB64, sourceEui=0017880103D08243, lastHopLqi=255, lastHopRssi=-41, relayList=F753]

2020-07-26 15:30:57.758 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0000, clusterId=8021, sourceEndpoint=0, destinationEndpoint=0, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=97], lastHopLqi=255, lastHopRssi=-41, sender=CB64, bindingIndex=255, addressIndex=255, messageContents=71 8C]

2020-07-26 15:30:57.761 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=CB64/0, destinationAddress=0000/0, profile=0000, cluster=8021, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=97, rssi=-41, lqi=FF, payload=71 8C]

2020-07-26 15:30:57.763 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [CB64/0 -> 0000/0, cluster=8021, TID=71, status=TABLE_FULL]

2020-07-26 15:30:57.765 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [CB64/0 -> 0000/0, cluster=8021, TID=71, status=TABLE_FULL] 

2020-07-26 15:30:57.768 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [CB64/0 -> 0000/0, cluster=8021, TID=71, status=TABLE_FULL] ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=264, state=ACKED, sendCnt=1, command=BindRequest [0000/0 -> CB64/0, cluster=0021, TID=71, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=6, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]]

2020-07-26 15:30:57.770 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=0017880103D08243 queueTime=266, state=COMPLETE, sendCnt=1, command=BindRequest [0000/0 -> CB64/0, cluster=0021, TID=71, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=6, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]]

2020-07-26 15:30:57.772 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-07-26 15:30:57.770 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 0017880103D08243: Failed to bind on off control cluster

2020-07-26 15:30:57.774 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0017880103D08243: transactionComplete COMPLETE 0

2020-07-26 15:30:57.775 [ERROR] [converter.ZigBeeConverterSwitchLevel] - 0017880103D08243: Error opening device level controls

2020-07-26 15:30:57.778 [INFO ] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880103D08243: Channel zigbee:device:0137F59F:0017880103d08243:0017880103D08243_11_dimmer failed to initialise device

I also did some searching around and found this thread (Zigbee Binding fails to initialize dimmer) and an corresponding issue (https://github.com/openhab/org.openhab.binding.zigbee/issues/522).

Maybe there’s some connection? Do you have any idea on this one?

Thanks and best!

[guy-inkognito (Guy)]

For reference if anyone stumbles over this thread. The issue was addressed here and the root cause identified:

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

Ok, now we need to know what this device is? The issue is that the device is reporting that the binding table is full. I’ve seen in the past with some old Hue bulbs that they only have a single table entry. It could be a similar situation here, or it could be that we’ve somehow filled it - to answer that we’d need to do some more work. Let me check if that’s easy or hard…

Currently the only way to solve it is to use an explicit autoupdate=true on the effected items. You may find comprehensive information on the why in the mentioned thread.