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

guy-inkognito · August 20, 2020, 4:23pm

Here you go:

2020-08-20 18:21:49.700 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 0017880103D08243: Failed to bind level control cluster

2020-08-20 18:21:49.941 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 0017880103D08243: Failed to bind on off control cluster

2020-08-20 18:21:49.943 [TRACE] [converter.ZigBeeConverterSwitchLevel] - 0017880103D08243: Error opening device level controls

2020-08-20 18:21:49.945 [ERROR] [converter.ZigBeeConverterSwitchLevel] - 0017880103D08243: Error opening device level controls

2020-08-20 18:21:49.946 [INFO ] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880103D08243: Channel zigbee:device:0137F59F:0017880103d08243:0017880103D08243_11_dimmer failed to initialise device

chris · August 20, 2020, 4:27pm

Sorry to be a pain - can you add some more debugging please.

log:set debug com.zsmartsystems.zigbee.ZigBeeNetworkManager

Hopefully that will tell me why this fails.

guy-inkognito · August 20, 2020, 4:29pm

No worries, happy to provide:

2020-08-20 18:29:22.356 [me.event.ThingUpdatedEvent] - Thing 'zigbee:device:0137F59F:0017880103d08243' has been updated.

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

2020-08-20 18:29:22.358 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> CB64/0, cluster=0021, TID=AC, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]

2020-08-20 18:29:22.363 [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=BD, rssi=--, lqi=--, payload=AC 43 82 D0 03 01 88 17 00 0B 00 03 03 46 F6 3A 0D 00 6F 0D 00 01]

2020-08-20 18:29:22.512 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=AC state=RX_ACK

2020-08-20 18:29:22.602 [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=9B, rssi=-44, lqi=FF, payload=AC 00]

2020-08-20 18:29:22.604 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [CB64/0 -> 0000/0, cluster=8021, TID=AC, status=SUCCESS]

2020-08-20 18:29:22.606 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ConfigureReportingCommand [Color Control: 0000/0 -> CB64/11, cluster=0300, TID=AD, records=[AttributeReportingConfigurationRecord [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=7, direction=0, minimumReportingInterval=1, maximumReportingInterval=7200, reportableChange=1]]]

2020-08-20 18:29:22.608 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=173, commandId=6]

2020-08-20 18:29:22.610 [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=BE, rssi=--, lqi=--, payload=00 AD 06 00 07 00 21 01 00 20 1C 01 00]

2020-08-20 18:29:22.754 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=AD state=RX_ACK

2020-08-20 18:29:22.844 [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=9C, rssi=-44, lqi=FF, payload=18 AD 0B 06 82]

2020-08-20 18:29:22.845 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=173, commandId=11]

2020-08-20 18:29:22.847 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [Color Control: CB64/11 -> 0000/1, cluster=0300, TID=AD, commandIdentifier=6, statusCode=UNSUP_GENERAL_COMMAND]

2020-08-20 18:29:22.849 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ConfigureReportingCommand [Color Control: 0000/0 -> CB64/11, cluster=0300, TID=AE, records=[AttributeReportingConfigurationRecord [attributeDataType=ENUMERATION_8_BIT, attributeIdentifier=8, direction=0, minimumReportingInterval=1, maximumReportingInterval=7200]]]

2020-08-20 18:29:22.851 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=174, commandId=6]

2020-08-20 18:29:22.853 [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=BF, rssi=--, lqi=--, payload=00 AE 06 00 08 00 30 01 00 20 1C]

2020-08-20 18:29:23.003 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=AE state=RX_ACK

2020-08-20 18:29:23.093 [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=9D, rssi=-45, lqi=FF, payload=18 AE 0B 06 82]

2020-08-20 18:29:23.095 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=174, commandId=11]

2020-08-20 18:29:23.096 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [Color Control: CB64/11 -> 0000/1, cluster=0300, TID=AE, commandIdentifier=6, statusCode=UNSUP_GENERAL_COMMAND]

2020-08-20 18:29:23.099 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> CB64/0, cluster=0021, TID=AF, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=8, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]

2020-08-20 18:29:23.101 [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=C0, rssi=--, lqi=--, payload=AF 43 82 D0 03 01 88 17 00 0B 08 00 03 46 F6 3A 0D 00 6F 0D 00 01]

2020-08-20 18:29:23.244 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=AF state=RX_ACK

2020-08-20 18:29:23.336 [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=9E, rssi=-45, lqi=FF, payload=AF 8C]

2020-08-20 18:29:23.339 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [CB64/0 -> 0000/0, cluster=8021, TID=AF, status=TABLE_FULL]

2020-08-20 18:29:23.343 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 0017880103D08243: Failed to bind level control cluster

2020-08-20 18:29:23.347 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> CB64/0, cluster=0021, TID=B0, srcAddress=0017880103D08243, srcEndpoint=11, bindCluster=6, dstAddrMode=3, dstAddress=000D6F000D3AF646, dstEndpoint=1]

2020-08-20 18:29:23.351 [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=C1, rssi=--, lqi=--, payload=B0 43 82 D0 03 01 88 17 00 0B 06 00 03 46 F6 3A 0D 00 6F 0D 00 01]

2020-08-20 18:29:23.494 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=B0 state=RX_ACK

2020-08-20 18:29:23.586 [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=9F, rssi=-44, lqi=FF, payload=B0 8C]

2020-08-20 18:29:23.589 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [CB64/0 -> 0000/0, cluster=8021, TID=B0, status=TABLE_FULL]

2020-08-20 18:29:23.595 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - 0017880103D08243: Failed to bind on off control cluster

2020-08-20 18:29:23.599 [TRACE] [converter.ZigBeeConverterSwitchLevel] - 0017880103D08243: Error opening device level controls

2020-08-20 18:29:23.603 [ERROR] [converter.ZigBeeConverterSwitchLevel] - 0017880103D08243: Error opening device level controls

2020-08-20 18:29:23.607 [INFO ] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880103D08243: Channel zigbee:device:0137F59F:0017880103d08243:0017880103D08243_11_dimmer failed to initialise device

chris · August 20, 2020, 4:39pm

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…

chris · August 20, 2020, 4:40pm

Ok, the good news is it’s easy

From the console, type the following -:

zigbee bindtable 0xCB64

guy-inkognito · August 20, 2020, 4:45pm

Indeed it’s a hue tunable white bulb for the example I’ve provided:

hardwareVersion	1
modelId	LTW010
vendor	Philips
zigbee_applicationVersion	2
zigbee_datecode	20181115

I experience similar problems with dimmer devices from Paulmann as well. Bitron wall plug devices are ok.

I’m happy to assist with more info. Maybe I need to shift to tomorrow - the childen … But let’s see

chris · August 20, 2020, 4:47pm

Ok, thanks. If you can run the above console command and provide the output it would be useful.

I must say I’m a little surprised that modern devices have such limited binding table sizes

guy-inkognito · August 20, 2020, 4:47pm

The command unfortunately just provides:

Error: Exception during command execution (IllegalArgumentException): Node '0xCB64' is not found.

chris · August 20, 2020, 4:48pm

Hmm - try replacing the 0xcb64 with 52068

guy-inkognito · August 20, 2020, 4:49pm

chris · August 20, 2020, 4:51pm

Hmmm - so looks like it only have 1 slot then

But hey - at least you’ll get colour updates

As I said, I’m surprised that these days binding tables aren’t 8 or 16 entries long - 1 is just, well, I’ll let you choose an appropriate word

guy-inkognito · August 20, 2020, 4:53pm

Haha, I see

But it’s right - the color updates, I can confirm. I wonder what changed though - the device used to work properly a while ago…

chris · August 20, 2020, 4:57pm

If you still have a few minutes, can you also supply the debug log when running the binding table command? I want to double check some things there…

guy-inkognito · August 20, 2020, 5:00pm

Happy to do:

2020-08-20 18:59:48.296 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementBindRequest [0000/0 -> CB64/0, cluster=0033, TID=23, startIndex=0]

2020-08-20 18:59:48.299 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=CB64/0, profile=0000, cluster=0033, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=D2, rssi=--, lqi=--, payload=23 00]

2020-08-20 18:59:48.418 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=23 state=RX_ACK

2020-08-20 18:59:48.517 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=CB64/0, destinationAddress=0000/0, profile=0000, cluster=8033, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=B8, rssi=-56, lqi=FF, payload=23 00 01 00 01 43 82 D0 03 01 88 17 00 0B 00 03 03 46 F6 3A 0D 00 6F 0D 00 01]

2020-08-20 18:59:48.519 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ManagementBindResponse [CB64/0 -> 0000/0, cluster=8033, TID=23, status=SUCCESS, bindingTableEntries=1, startIndex=0, bindingTableList=[BindingTable [srcAddr=0017880103D08243/11, dstAddr=000D6F000D3AF646/1, clusterId=0300]]]

chris · August 20, 2020, 5:32pm

Thanks. I’m not sure why it would have worked previously - I would be surprised if an updated firmware would decrease the binding table size, although it’s not impossible.

Leave this with me. I can see there’s another way to set the binding table to allow multiple clusters so I need to investigate that as it would also resolve this.

Benjy · August 20, 2020, 11:11pm

Thanks for looking into it @chris! Completely understand your decision to veto the command state update, that makes the most sense to me out of the two ways.

Just to update I thought this was happening with some IKEA tradfri bulbs as well as for the Hue bulbs, but after setting the colour once, these are working normally and are now updating.

That limits the issue to the Phillips Hue bulbs I updated the firmware for. As you guided @guy-inkognito, I tried looking at the binding table for any of my colour bulbs and got something a little more puzzling, but this might be an error between my screen and the chair :

openhab> zigbee bindtable 4059
Binding table read error: UNSUPPORTED

2020-08-21 00:05:03.439 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 1 outstanding
2020-08-21 00:05:03.440 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 001788011029F4B8: transactionComplete FAILED 1
2020-08-21 00:05:03.442 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 001788011029F4B8: transactionComplete exceeded retries 2
2020-08-21 00:05:03.443 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction terminated: ZigBeeTransaction [ieeeAddress=001788011029F4B8 queueTime=41693, state=FAILED, sendCnt=2, command=ManagementRoutingRequest [0000/0 -> 7E6F/0, cluster=0032, TID=50, startIndex=0]]
2020-08-21 00:05:03.445 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 50 -> RX_NAK == FAILED
2020-08-21 00:05:03.481 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:NACK:BE
2020-08-21 00:05:03.483 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisNackMessageEvent [messageId=190]
2020-08-21 00:05:03.485 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=51 state=RX_NAK
2020-08-21 00:05:03.486 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=51, state=RX_NAK, outstanding=1
2020-08-21 00:05:03.488 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=001788011029F4B8 queueTime=4797, state=FAILED, sendCnt=1, command=ManagementRoutingRequest [0000/0 -> 7E6F/0, cluster=0032, TID=51, startIndex=0]]
2020-08-21 00:05:03.490 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2020-08-21 00:05:03.492 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 001788011029F4B8: transactionComplete FAILED 0
2020-08-21 00:05:03.502 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 001788011029F4B8: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=001788011029F4B8 queueTime=4810, state=WAITING, sendCnt=1, command=ManagementRoutingRequest [0000/0 -> 7E6F/0, cluster=0032, TID=51, startIndex=0]]
2020-08-21 00:05:03.505 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 51 -> RX_NAK == WAITING
2020-08-21 00:05:03.927 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2020-08-21 00:05:03.929 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisDisplayNetworkInformationCommand [device=null, channel=null, power=null, panId=null, epanId=null]
2020-08-21 00:05:03.932 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data:AT+N?

2020-08-21 00:05:03.966 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:+N=COO,11,-07,09AC,1692DB66BB61E39C
2020-08-21 00:05:03.968 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:OK
2020-08-21 00:05:03.971 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisDisplayNetworkInformationCommand [device=COO, channel=11, power=-7, panId=2476, epanId=1692DB66BB61E39C, status=SUCCESS]
2020-08-21 00:05:04.934 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2020-08-21 00:05:04.935 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisDisplayNetworkInformationCommand [device=null, channel=null, power=null, panId=null, epanId=null]
2020-08-21 00:05:04.938 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data:AT+N?

2020-08-21 00:05:04.971 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:+N=COO,11,-07,09AC,1692DB66BB61E39C
2020-08-21 00:05:04.973 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:OK
2020-08-21 00:05:04.976 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisDisplayNetworkInformationCommand [device=COO, channel=11, power=-7, panId=2476, epanId=1692DB66BB61E39C, status=SUCCESS]
2020-08-21 00:05:05.101 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880100FFEF9F: Configuration received: {zigbee_macaddress=0017880100FFEF9F, zigbee_initialise_device=true}
2020-08-21 00:05:05.104 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880100FFEF9F: Configuration update: Ignored zigbee_macaddress as no change
2020-08-21 00:05:05.106 [DEBUG] [e.internal.ZigBeeDeviceConfigHandler] - Configuration update: Ignored zigbee_macaddress as no change
2020-08-21 00:05:05.116 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880100FFEF9F: Configuration updated: Reinitialise device
2020-08-21 00:05:05.119 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880100FFEF9F: Initializing device
2020-08-21 00:05:05.122 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880100FFEF9F: Initializing channel zigbee:device:04000B8C:0017880100ffef9f:0017880100FFEF9F_11_colortemperature with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterColorTemperature@3de447
2020-08-21 00:05:05.125 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0017880100FFEF9F: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=0017880100FFEF9F queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> 0FDB/0, cluster=0021, TID=--, srcAddress=0017880100FFEF9F, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D05393B, dstEndpoint=1]]
2020-08-21 00:05:05.127 [DEBUG] [transaction.ZigBeeTransactionManager] - 0FDB/0: Sending ZigBeeTransaction [ieeeAddress=0017880100FFEF9F queueTime=3, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> 0FDB/0, cluster=0021, TID=52, srcAddress=0017880100FFEF9F, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D05393B, dstEndpoint=1]]
2020-08-21 00:05:05.129 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2020-08-21 00:05:05.132 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> 0FDB/0, cluster=0021, TID=52, srcAddress=0017880100FFEF9F, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D05393B, dstEndpoint=1]
2020-08-21 00:05:05.136 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0FDB/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=C3, rssi=--, lqi=--, payload=52 9F EF FF 00 01 88 17 00 0B 00 03 03 3B 39 05 0D 00 6F 0D 00 01]
2020-08-21 00:05:05.139 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendUnicastCommand [address=4059, sourceEp=0, destEp=0, profileId=0, clusterId=33, messageData=52 9F EF FF 00 01 88 17 00 0B 00 03 03 3B 39 05 0D 00 6F 0D 00 01, messageId=null]
2020-08-21 00:05:05.141 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2020-08-21 00:05:05.143 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisSendUnicastCommand [address=4059, sourceEp=0, destEp=0, profileId=0, clusterId=33, messageData=52 9F EF FF 00 01 88 17 00 0B 00 03 03 3B 39 05 0D 00 6F 0D 00 01, messageId=null]
R�ïÿ�08-21 00:05:05.152 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data:AT+SENDUCASTB:16,0FDB,00,00,0000,0021
o    ;9

PuTTY2020-08-21 00:05:05.192 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SEQ:BF
2020-08-21 00:05:05.193 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:OK
2020-08-21 00:05:05.229 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisSendUnicastCommand [address=4059, sourceEp=0, destEp=0, profileId=0, clusterId=33, messageData=52 9F EF FF 00 01 88 17 00 0B 00 03 03 3B 39 05 0D 00 6F 0D 00 01, messageId=191, status=SUCCESS]
2020-08-21 00:05:05.230 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=52 state=TX_ACK
2020-08-21 00:05:05.243 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=52, state=TX_ACK, outstanding=1
2020-08-21 00:05:05.245 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 52 -> TX_ACK == TRANSMITTED
2020-08-21 00:05:05.440 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:ACK:BF
2020-08-21 00:05:05.441 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisAckMessageEvent [messageId=191]
2020-08-21 00:05:05.442 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=52 state=RX_ACK
2020-08-21 00:05:05.443 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=52, state=RX_ACK, outstanding=1
2020-08-21 00:05:05.443 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 52 -> RX_ACK == ACKED
2020-08-21 00:05:05.490 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:0FDB,0000,00,00,8021,02:R�,-58,C6
2020-08-21 00:05:05.491 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=4059, profileId=0, destinationEp=0, sourceEp=0, clusterId=32801, messageData=52 84, rssi=-88, lqi=198]
2020-08-21 00:05:05.492 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0FDB/0, destinationAddress=0000/0, profile=0000, cluster=8021, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=52 84]
2020-08-21 00:05:05.492 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [0FDB/0 -> 0000/0, cluster=8021, TID=52, status=NOT_SUPPORTED]
2020-08-21 00:05:05.493 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [0FDB/0 -> 0000/0, cluster=8021, TID=52, status=NOT_SUPPORTED]
2020-08-21 00:05:05.494 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [0FDB/0 -> 0000/0, cluster=8021, TID=52, status=NOT_SUPPORTED] ZigBeeTransaction [ieeeAddress=0017880100FFEF9F queueTime=370, state=ACKED, sendCnt=1, command=BindRequest [0000/0 -> 0FDB/0, cluster=0021, TID=52, srcAddress=0017880100FFEF9F, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D05393B, dstEndpoint=1]]
2020-08-21 00:05:05.496 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=0017880100FFEF9F queueTime=371, state=COMPLETE, sendCnt=1, command=BindRequest [0000/0 -> 0FDB/0, cluster=0021, TID=52, srcAddress=0017880100FFEF9F, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D05393B, dstEndpoint=1]]
2020-08-21 00:05:05.496 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880100FFEF9F: Initializing channel zigbee:device:04000B8C:0017880100ffef9f:0017880100FFEF9F_11_color with org.openhab.binding.zigbee.internal.converter.ZigBeeConverterColorColor@c49fc8
2020-08-21 00:05:05.497 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2020-08-21 00:05:05.498 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0017880100FFEF9F: transactionComplete COMPLETE 0
2020-08-21 00:05:05.498 [DEBUG] [.converter.ZigBeeConverterColorColor] - 0017880100FFEF9F: Device supports Hue/Saturation color set of commands
2020-08-21 00:05:05.499 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0017880100FFEF9F: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=0017880100FFEF9F queueTime=0, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> 0FDB/0, cluster=0021, TID=--, srcAddress=0017880100FFEF9F, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D05393B, dstEndpoint=1]]
2020-08-21 00:05:05.501 [DEBUG] [transaction.ZigBeeTransactionManager] - 0FDB/0: Sending ZigBeeTransaction [ieeeAddress=0017880100FFEF9F queueTime=2, state=WAITING, sendCnt=0, command=BindRequest [0000/0 -> 0FDB/0, cluster=0021, TID=53, srcAddress=0017880100FFEF9F, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D05393B, dstEndpoint=1]]
2020-08-21 00:05:05.502 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding
2020-08-21 00:05:05.504 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0000/0 -> 0FDB/0, cluster=0021, TID=53, srcAddress=0017880100FFEF9F, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D05393B, dstEndpoint=1]
2020-08-21 00:05:05.506 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/0, destinationAddress=0FDB/0, profile=0000, cluster=0021, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=C4, rssi=--, lqi=--, payload=53 9F EF FF 00 01 88 17 00 0B 00 03 03 3B 39 05 0D 00 6F 0D 00 01]
2020-08-21 00:05:05.507 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendUnicastCommand [address=4059, sourceEp=0, destEp=0, profileId=0, clusterId=33, messageData=53 9F EF FF 00 01 88 17 00 0B 00 03 03 3B 39 05 0D 00 6F 0D 00 01, messageId=null]
2020-08-21 00:05:05.508 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
2020-08-21 00:05:05.509 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis: TelegesisSendUnicastCommand [address=4059, sourceEp=0, destEp=0, profileId=0, clusterId=33, messageData=53 9F EF FF 00 01 88 17 00 0B 00 03 03 3B 39 05 0D 00 6F 0D 00 01, messageId=null]
S�ïÿ�08-21 00:05:05.512 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis Data:AT+SENDUCASTB:16,0FDB,00,00,0000,0021
o    ;9

PuTTY2020-08-21 00:05:05.556 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:SEQ:C0
2020-08-21 00:05:05.556 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:OK
2020-08-21 00:05:05.557 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisSendUnicastCommand [address=4059, sourceEp=0, destEp=0, profileId=0, clusterId=33, messageData=53 9F EF FF 00 01 88 17 00 0B 00 03 03 3B 39 05 0D 00 6F 0D 00 01, messageId=192, status=SUCCESS]
2020-08-21 00:05:05.558 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=53 state=TX_ACK
2020-08-21 00:05:05.559 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=53, state=TX_ACK, outstanding=1
2020-08-21 00:05:05.560 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 53 -> TX_ACK == TRANSMITTED
2020-08-21 00:05:06.063 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:RX:0FDB,0000,00,00,8021,02:S�,-58,FE
2020-08-21 00:05:06.064 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=4059, profileId=0, destinationEp=0, sourceEp=0, clusterId=32801, messageData=53 84, rssi=-88, lqi=254]
2020-08-21 00:05:06.066 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0FDB/0, destinationAddress=0000/0, profile=0000, cluster=8021, addressMode=null, radius=0, apsSecurity=false, ackRequest=false, apsCounter=--, rssi=--, lqi=--, payload=53 84]
2020-08-21 00:05:06.068 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [0FDB/0 -> 0000/0, cluster=8021, TID=53, status=NOT_SUPPORTED]
2020-08-21 00:05:06.069 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [0FDB/0 -> 0000/0, cluster=8021, TID=53, status=NOT_SUPPORTED]
2020-08-21 00:05:06.072 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: BindResponse [0FDB/0 -> 0000/0, cluster=8021, TID=53, status=NOT_SUPPORTED] ZigBeeTransaction [ieeeAddress=0017880100FFEF9F queueTime=572, state=TRANSMITTED, sendCnt=1, command=BindRequest [0000/0 -> 0FDB/0, cluster=0021, TID=53, srcAddress=0017880100FFEF9F, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D05393B, dstEndpoint=1]]
2020-08-21 00:05:06.074 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction response received - waiting TX_ACK: ZigBeeTransaction [ieeeAddress=0017880100FFEF9F queueTime=574, state=RESPONDED, sendCnt=1, command=BindRequest [0000/0 -> 0FDB/0, cluster=0021, TID=53, srcAddress=0017880100FFEF9F, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D05393B, dstEndpoint=1]]
2020-08-21 00:05:06.157 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis Data:ACK:C0
2020-08-21 00:05:06.158 [DEBUG] [gesis.internal.TelegesisFrameHandler] - RX Telegesis: TelegesisAckMessageEvent [messageId=192]
2020-08-21 00:05:06.160 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=53 state=RX_ACK
2020-08-21 00:05:06.161 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=53, state=RX_ACK, outstanding=1
2020-08-21 00:05:06.164 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=0017880100FFEF9F queueTime=664, state=COMPLETE, sendCnt=1, command=BindRequest [0000/0 -> 0FDB/0, cluster=0021, TID=53, srcAddress=0017880100FFEF9F, srcEndpoint=11, bindCluster=768, dstAddrMode=3, dstAddress=000D6F000D05393B, dstEndpoint=1]]
2020-08-21 00:05:06.163 [ERROR] [.converter.ZigBeeConverterColorColor] - 0017880100FFEF9F: Error 0x84 setting server binding
2020-08-21 00:05:06.165 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding
2020-08-21 00:05:06.166 [INFO ] [ng.zigbee.handler.ZigBeeThingHandler] - 0017880100FFEF9F: Channel zigbee:device:04000B8C:0017880100ffef9f:0017880100FFEF9F_11_color failed to initialise device
2020-08-21 00:05:06.166 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - 0017880100FFEF9F: transactionComplete COMPLETE 0
2020-08-21 00:05:06.168 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 53 -> RX_ACK == COMPLETE

chris · August 21, 2020, 7:50am

Thanks @Benjy - I’m glad it’s now isolated to a problem with Hue bulbs.

I will try out this other way I’ve found to set the binding table - I need to add some code to implement this in the stack first so it’s not a super quick fix, but I’ll try and at least run some tests over the coming few days. I have a Hue white bulb here somewhere - it is quite new so may work differently than the one(s) you guys have.

At least it seems likely we’ve got to the root cause of the issue, and understanding a problem is a good chunk of the way to resolving it. I just hope that this other binding method is a workable solution - it allows adding multiple clusters in one call so if Hue supports that it will resolve this. The issue then will be if every other bulb supports it, or if I need to add some convoluted system that can use both (I suspect this is where I will end up!).

If the Hue bulb doesn’t support the other binding mechanism, then I’m not sure where to go with this, but let’s worry about that next week

guy-inkognito · August 23, 2020, 12:27pm

Thanks @chris and @Benjy for figuring out the issue!

I just want to add the remark, that I can reproduce the problem also with LED stripe dimmers from Paulmann and Innr bulbs. So I think it’s not limited to older Hue bulbs only.

chris · August 23, 2020, 12:31pm

I have a LOT of Paulmann bulbs here (we’re doing some work with them at the moment) so I’ll have a look at their bulbs. I also have some Innr, but really can’t test everything. If bulbs are only using single binding table entry, then that’s really quite poor in modern times when memory should not be an issue.

Unfortunately the option I thought I’d found to set the binding table in a different way is not possible - it’s not the purpose of the command, so it’s likely that we will have to live with this issue.

guy-inkognito · August 23, 2020, 12:44pm

It’s really a pity though that manufacturers build these kind of stuff

In that case (so bulbs or devices fail to initialize for that reason) maybe it’d be a good idea to make the binding not veto the autoupdate? Otherwise users probalby won’t have any chance to figure out they need to do an manual autoupdate=true override to make the items state updates work “somewhat correctly”. What do you think?