Excellent, thanks Chris. I’ll do that as soon as I can. Just to make sure, when you say latest binding, you mean the snapshot and not the stable version right?
Correct - yes, I mean the snapshot (thanks for clarifying - I should have been clearer).
I think I’ve gone through quite some of the steps you described and created the requested logs in debug mode already. You may find them here:
Maybe it helps avoid double-work.
Are these issues the same?
Here, you say -:
However I understood the issue here is different
I understood this to mean that it doesn’t update the state if it’s commanded directly - ie via switch or other system.
Maybe I’ve misinterpreted the question? IF so, then my answer is also not relevant as I was assuming the issue is relating to reporting of device states
I had a look at that topic and it looks like both. If I toggle a light ON in a sitemap the physical light turns on but the state remains UNDEF. This is the same as if something else changes its state, e.g. a switch. If I send a REFRESH command to the thing, nothing happens and the Items linked to the Thing remains UNDEF
This only seems to be happening with bulbs, regardless of manufacturer. The battery voltage in my remotes are updating and my IKEA Fytur blinds are reporting instantly, regardless of how their states are changed.
2020-08-20 14:36:30.650 [vent.ItemStateChangedEvent] - SecondBedroom_Blinds_Position changed from 0 to 1
2020-08-20 14:36:31.692 [vent.ItemStateChangedEvent] - SecondBedroom_Blinds_Position changed from 1 to 10
2020-08-20 14:36:32.717 [vent.ItemStateChangedEvent] - SecondBedroom_Blinds_Position changed from 10 to 18
2020-08-20 14:36:33.754 [vent.ItemStateChangedEvent] - SecondBedroom_Blinds_Position changed from 18 to 27
2020-08-20 14:36:34.786 [vent.ItemStateChangedEvent] - SecondBedroom_Blinds_Position changed from 27 to 35
2020-08-20 14:36:35.821 [vent.ItemStateChangedEvent] - SecondBedroom_Blinds_Position changed from 35 to 44
2020-08-20 14:36:36.848 [vent.ItemStateChangedEvent] - SecondBedroom_Blinds_Position changed from 44 to 52
2020-08-20 14:36:37.878 [vent.ItemStateChangedEvent] - SecondBedroom_Blinds_Position changed from 52 to 61
2020-08-20 14:36:38.917 [vent.ItemStateChangedEvent] - SecondBedroom_Blinds_Position changed from 61 to 69
2020-08-20 14:36:39.952 [vent.ItemStateChangedEvent] - SecondBedroom_Blinds_Position changed from 69 to 78
2020-08-20 14:36:40.988 [vent.ItemStateChangedEvent] - SecondBedroom_Blinds_Position changed from 78 to 86
2020-08-20 14:36:42.021 [vent.ItemStateChangedEvent] - SecondBedroom_Blinds_Position changed from 86 to 95
2020-08-20 14:36:43.051 [vent.ItemStateChangedEvent] - SecondBedroom_Blinds_Position changed from 95 to 100
@Benjy, maybe you can have look at the last post in the mentioned thread (Items receive commands but stopped to update their states) and check if you experience similar behaviour when trying to trigger a thing initialization. This would be an indicator that there may be a connection?
Ok, so the bulb should report back its state. When the command comes in from the UI, the UI doesn’t get updated at that point - we expect the device to send a report to say that it has changed state. This should normally come in within a second, and then the UI should be updated.
@chris, it doesn’t matter how long I wait, there’s no returned updated state unfortunately, it remains UNDEF.
Interesting, @guy-inkognito is correct. I found a single bulb that’s working as expected. Checking the initialise switch works fine on that. For every other bulb it is not working:
2020-08-20 14:54:37.582 [ERROR] [converter.ZigBeeConverterSwitchLevel] - 00178801102B5321: Error opening device level controls
2020-08-20 14:54:37.584 [INFO ] [ng.zigbee.handler.ZigBeeThingHandler] - 00178801102B5321: Channel zigbee:device:04000B8C:00178801102b5321:00178801102B5321_11_dimmer failed to initialise device
Debug logs for initialisation of a single broken Thing: (still on latest stable)
openhab.log (23.5 KB)
@chris, is it still worth recording everything in the step-by-step you posted?
That’s understood - I was just trying to give an overview how how it is meant to work.
The problem we fight against here is getting a system that works for everyone under all conditions. We made the change to veto recently to solve a problem with another set of users because the other problem here is when devices DO respond how I said, and that can cause other difficulties…
Eg… If we have blinds - you start from 0%, send the command via the UI to go to 100%, and what the user will see is 0, 100, 10, 20 … 100. That upsets people, and it’s caused by the state being set by the command (ie the first 100 in this sequence). If we remove that, and devices do not report, then we get nothing - this is the situation that you have. So we add this back, and we just change to upsetting a different group of users…
You could change the autoupdatepolicy to recommend to see if that fixes it.
Ideally, the binding would change this for each channel, depending on what happens - or it could do some “magic” and set the state “some period” after sending the command - if the command was ack’d, and if no report was received. These sort of things would be a better and more dynamic (by which I mean better able to cope with different situations). But it also takes more work to think this through and implement 
.
Thanks for your feedback, @chris!
However, after my testing as described in the other thread, I came to the conclusion that most likely the issue is not caused by the autoupdate policy but rather by something going wrong with the device initialization.
State update works as expected for devices that do not show the initialization error @Benjy just described, at least for me. Maybe @Benjy: Does the device that seems to initialize correctly also correctly change its state on your environment?
Well, yes, that error means that the reporting is not configured, so yes, resolving that would hopefully fix it, but that doesn’t change what I said about the way that the auto update policy works.
For what it’s worth, I don’t think it is bad to have channel autoupdate policy to “veto”. This causes no errors, only highlights a deficiency in device reporting.
The user can always set the Items autoupdate to true (force) and override the veto. That’s a kludge to partially circumvent the device reporting deficiency. It’s not “the answer”, just as removing channel veto is not the answer.
The root problem is the device failure to report.
Personally, I tink the autoupdate mechanism as it is at the moment is really good. It solves the “slider jump” thing and actually represents the “device truth”. For my personal feeling that’s how it should be. And in case you need another behavior you’re always free to change the autoupdate mechanism by e.g. setting it to an explicit true.
Yes, it’s a bit difficult to understand in the first place, but hey … 
Do you have any impulse on how to “repair” the device initialization though?
Please can you enable trace logging on the above class (org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchLevel).
The error logged here is actually not printing the correct text - I’ll update that, but I’d like to see trace output when this happens.
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
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.
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
1 Like
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…
Ok, the good news is it’s easy 
From the console, type the following -:
zigbee bindtable 0xCB64
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