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

Yes I understand the problem, seen with ramping dimmers etc.

UI? You mean, autoupdate acting in its usual default way in response to command from UI (or rule)

Does that mean some Zigbee channels do indeed have Veto policy set? (With the implication that the end device must then be configured to send timely updates)

I’m not 100% sure if it’s autoupdate, or just the UI, but the issue is the user clicks a dimmer to (say) 70% when it’s currently 0%. The dimmer then shows 70% in the UI even without autoupdate. Autoupdate may also set it to 70%, but then for some devices that send multiple reports, you may get a reading of 20%, then 60%, then 70%… So the user sees 0, 70, 20, 60, 70…

Yes, we were trying to get rid of exactly this issue since the ZigBee binding will configure devices to report their state and it was causing problems not having this set. Maybe I need to look at adding more intelligence into the binding to try and work out dynamically how to set this when it’s creating the channel definitions…

Okay. The OP seems to have the issue that his particular Zigbee config/devices are not reporting new status, plus, were by default “vetoing” autoupdate. That might be configuration error, I have now realized, or might be unwanted side effect of your change. Change seems more likely as effect noticed after update.

Not to say that I do not think there is something wrong with OPs config, by not reporting status. I’m just not sure if consequent suppression of autoupdate was intended in this fault situation.

Needs a bit more unpicking here really.

Thanks all for the interesting discussion and the details!

Sounds quite reasonable to me that this could be the reason. I’ve did some more testing with some unused devices:

  • Bitron wall plug dimmers + Osram wall plug switches [working]
  • Bulbs from Philips & Innr + Paulmann dimmers [not working]

Thus, as this is consistent within device manufacturers, it could probably be that the latter ones are not correctly reporting back their states?

As using an explicit autoupdate=true in the channel configurations make it work again, I’d assume this again overrides the update logic and triggers correct behaviour.

I do have a background in software development a couple of years ago but no deep knowledge of the OH software itself. So if you point me into the right direction I’m happy to - as far as possible for me - further assist with any investigation if required.

Thanks!

I would say so. I thought the Zigbee binding actively polled for status, but I do not know and that’s where my knowledge ends.

The ZigBee binding tries hard to avoid polling - polling is generally not a good thing as it needlessly consumes bandwidth. Both ZigBee and ZWave support systems for reporting change, and that’s what we try and use.

Of course some devices don’t support that, and then the binding will fall back to polling, but polling is relatively slow.

In general, most devices really should support reporting. If reporting configuration fails, then the binding will poll, but this is a much slower update than reporting.

Fair enough, I should RTFM


What should @guy-inkognito look at with respect to his ‘naughty’ devices? Are there device settings that could be checked, maybe with a tool?

Is there a means to see if the binding has, or should, fall back on to polling? A way to force poling if necessary? This suggests not

I’m further guessing a binding trace log may not be that helpful here … but should reveal operating uh mode?

Really I’d need to look at the detailed logs to see what is happening. The binding tries to select this sort of thing automatically - if reporting configuration works, then the binding will use reporting - if it doesn’t, it uses polling. This is automatic.

What I haven’t done is to adjust the auto update parameter during channel creation (as mentioned earlier). I could look at doing this automatically as well, but I’d need to find some time to work out how to detect this at the point that channels are being created.

I’m trying to work this sort of thing automatically as I don’t want to review logs every time some device does something differently (I’d spend my life looking at logs :slight_smile: ). The whole concept of the binding is to be dynamic and avoid the issue we see with the ZWave binding (which was written before dynamic channels were available in ESH) where we have to maintain a database. Self discovery of the device features is (IMHO) my best hope at keeping the support levels low :wink:

@guy-inkognito if you want to provide debug logs (as per the binding docs) showing the device initialisation phase, I will have a look to see what I can see.

I also need to know exactly what “not working” means - ie exactly what the conditions are that are being tested so there’s no confusion. I’m not trying to be difficult here, but I do want to be clear as to the exact test that is being done, and then get the relevant logs so I can tie up what is in the logs with what is physically happening.

Thanks.

2 Likes

I’ll put together a test scenario and provide the debug logs.

One additional question to be sure it’s useful: How can I correctly trigger the device initialization phase? Is it sufficient to power off and on the device? Or do I need to remove the thing and re-learn it to the binding? Or shall I use the initialize switch in the thing configuration UI?

In the meantime, here’s what “not working” means from my point of view. To make it clear I’d execute the following scenario while creating logs:

  • Remove all items except for one “working” and one “not working” with a very simple channel configuration like so:
Dimmer TestItem_Working {channel="zigbee:device:***:***_11_dimmer"}
Dimmer TestItem_NotWorking {channel="zigbee:device:***:***_11_dimmer"}
  • [Initialize both devices - see question above how to do so]
  • Trigger an item update via PaperUI Control for both
    ** Expectation: Both items receive the command. Item state of both gets updated to the value set via the UI within a couple of seconds
    ** What will probably happen: Both items receive the command. Item state of the “working” item gets updated within a couple of seconds. Item state of the “not working” item does not get updated
  • Wait half an hour or so until the “not working” device gets updated by polling mechanism (by looking into the logs a bit more detailed by myself (thanks @chris for the awesome log analyzer you have on your website!) I discovered that the state finally gets updated after like 20 minutes or so which perfectly fits the polling mechanics you described above)

Would you consider this sufficent or shall I change/add something on the scenario?

And no worries about being difficult of course - I’ve debugged enough software myself to know what it means. I’m very thankful for the support of all of you :slight_smile:

1 Like

Hello,

so here we go:

  • Defined items as written above
  • Set log level as in Zigbee binding doc
  • Stopped OH service
  • Cleaned cache
  • Rebooted: Logs start with reboot
  • Waited a while
  • Set TestItem_Working to 67 (14:06)
  • Set TestItem_NotWorking to 31 (14:07)

Behaviour was like described in my previous post.

Hope it helps! Thanks and have an nice weekend!


In case there’s something more I can provide or look at on my own, I’m happy to do so if you provide me with some guidance. Otherwise I’m looking forward to any insight from the logs hopefully.

Thx and cheers!

I think you may have needed to tag or reply to @chris for his further attention, he gets drawn into lots of stuff :wink:

1 Like

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 :wink:

Thanks @rossko57, you’re right :smiley:

@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"}

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.

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?

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.

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!

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

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.