Sylvania Smart+ Recessed RGBW (Zigbee) - values fluctuate when set

Thanks…

Here is what I get from the log viewer:

|Time|Node|Entry|

| — | — | — |

|10:16:28.031||COMMAND RECEIVED zigbee:device:stick:f0d1b80000069eef:F0D1B80000069EEF_1_colortemperature 22 [PercentType]|

|10:16:28.151||STATE UPDATE zigbee:device:stick:f0d1b80000069eef:F0D1B80000069EEF_1_colortemperature 75|

|10:16:32.498||STATE UPDATE zigbee:device:stick:f0d1b80000069eef:F0D1B80000069EEF_1_colortemperature 22|

Seems to confirm getting a state update with the currently set value (75), then another state update seconds later with the new value (22). The lamp itself, however, reflects the requested value (22) as soon as the request is sent. Not sure exactly what to make of it all. The logfile itself seems to offer more clues than the viewer alone but I’m not versed enough to make conclusions from what is there…

This is not likely to be a problem with the binding - it’s more likely to be caused by the framework trying to set the value, but because the binding is providing updates from the bulb (which I assume you want, otherwise you don’t know when someone changes the bulb) the two are fighting each other. I think you need to disable the updates from the framework, although I forget how at the moment.

Not sure if I’m going in the right direction but I tried creating an item with autoupdate=“false” as that seemed to be about all I could find in terms of suppressing framework updates…

No change in behavior though…

Not sure where to look so, if you happen to remember or find a link, let me know.

Thanks much!

Giving this a bump as it is still a problem for me.

I think I’ve read somewhere while researching this problem that there is an auto update policy that applies to things as well as what i’ve tried to do with my colortemp item.

Before I go down that road though I’d like to know if I’m on the right track here in terms of disabling updates from the framework.

Thanks much for the help so far. Even if I haven’t made progress on this particular problem, I’m learning a lot that could help down the road.

-Greg-

Still bothered by this… I’ve included another log here that is more detailed and includes debug/info logging for more than just the zigbee binding…

I hope someone has either seen this before and has solved it or at least understands the issue. It’s quite frustrating to watch my controls bouncing back and forth when trying to set a color or any such thing with these lights…

Thanks for any guidance - even if it’s to junk these lights and start over with something other than a zigbee based rgbw solution…

And, yes, I’ve uploaded this to the online logfile viewer but that hasn’t really shed any light on why I seem to get multiple update messages after a request… I’m not sure what to look for in that respect…

FWIW, the Color_Temperature value prior to the request below was 10…

2020-05-04 15:48:32.721 [ome.event.ItemCommandEvent] - Item 'BrooklynLight1_ColorTemperature' received command 89


2020-05-04 15:48:32.777 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - F0D1B80000069EEF: Command for channel zigbee:device:stick:f0d1b80000069eef:F0D1B80000069EEF_1_colortemperature --> 89 [PercentType]

2020-05-04 15:48:32.783 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - F0D1B80000069EEF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=F0D1B80000069EEF queueTime=0, state=WAITING, sendCnt=0, command=MoveToColorTemperatureCommand [Color Control: 0000/0 -> 09CC/1, cluster=0300, TID=--, colorTemperature=414, transitionTime=10]]

2020-05-04 15:48:32.791 [DEBUG] [transaction.ZigBeeTransactionManager] - 09CC/1: Sending ZigBeeTransaction [ieeeAddress=F0D1B80000069EEF queueTime=8, state=WAITING, sendCnt=0, command=MoveToColorTemperatureCommand [Color Control: 0000/0 -> 09CC/1, cluster=0300, TID=97, colorTemperature=414, transitionTime=10]]

2020-05-04 15:48:32.793 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-05-04 15:48:32.797 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: MoveToColorTemperatureCommand [Color Control: 0000/0 -> 09CC/1, cluster=0300, TID=97, colorTemperature=414, transitionTime=10]

2020-05-04 15:48:32.800 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=151, commandId=10]

2020-05-04 15:48:32.804 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=09CC/1, profile=0104, cluster=0300, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=1D, rssi=--, lqi=--, payload=01 97 0A 9E 01 0A 00]

2020-05-04 15:48:32.822 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=41]

2020-05-04 15:48:32.842 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=09CC, sourceEui=F0D1B80000069EEF, lastHopLqi=255, lastHopRssi=-56, relayList=]

2020-05-04 15:48:32.863 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=09CC, sourceEui=F0D1B80000069EEF, lastHopLqi=255, lastHopRssi=-56, relayList=]

2020-05-04 15:48:32.868 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=09CC, sourceEui=F0D1B80000069EEF, lastHopLqi=255, lastHopRssi=-56, relayList=]

2020-05-04 15:48:32.898 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0300, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=91], lastHopLqi=255, lastHopRssi=-56, sender=09CC, bindingIndex=255, addressIndex=255, messageContents=08 97 0B 0A 00]

2020-05-04 15:48:32.900 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=09CC/1, destinationAddress=0000/1, profile=0104, cluster=0300, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=91, rssi=-56, lqi=FF, payload=08 97 0B 0A 00]

2020-05-04 15:48:32.903 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=151, commandId=11]

2020-05-04 15:48:32.906 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [Color Control: 09CC/1 -> 0000/1, cluster=0300, TID=97, commandIdentifier=10, statusCode=SUCCESS]

2020-05-04 15:48:32.909 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DefaultResponse [Color Control: 09CC/1 -> 0000/1, cluster=0300, TID=97, commandIdentifier=10, statusCode=SUCCESS] 

2020-05-04 15:48:32.912 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: DefaultResponse [Color Control: 09CC/1 -> 0000/1, cluster=0300, TID=97, commandIdentifier=10, statusCode=SUCCESS] ZigBeeTransaction [ieeeAddress=F0D1B80000069EEF queueTime=131, state=DISPATCHED, sendCnt=1, command=MoveToColorTemperatureCommand [Color Control: 0000/0 -> 09CC/1, cluster=0300, TID=97, colorTemperature=414, transitionTime=10]]

2020-05-04 15:48:32.916 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=F0D1B80000069EEF queueTime=134, state=COMPLETE, sendCnt=1, command=MoveToColorTemperatureCommand [Color Control: 0000/0 -> 09CC/1, cluster=0300, TID=97, colorTemperature=414, transitionTime=10]]

2020-05-04 15:48:32.918 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-05-04 15:48:32.918 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=2508, apsFrame=EmberApsFrame [profileId=0104, clusterId=0300, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=41], messageTag=97, status=EMBER_SUCCESS, messageContents=]

2020-05-04 15:48:32.920 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - F0D1B80000069EEF: transactionComplete COMPLETE 0

2020-05-04 15:48:32.922 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=97 state=RX_ACK

2020-05-04 15:48:32.924 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0300, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=92], lastHopLqi=255, lastHopRssi=-56, sender=09CC, bindingIndex=255, addressIndex=255, messageContents=08 0C 0A 07 00 21 A6 00]

2020-05-04 15:48:32.924 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=97, state=RX_ACK, outstanding=0

2020-05-04 15:48:32.926 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=09CC/1, destinationAddress=0000/1, profile=0104, cluster=0300, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=92, rssi=-56, lqi=FF, payload=08 0C 0A 07 00 21 A6 00]

2020-05-04 15:48:32.928 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=12, commandId=10]

2020-05-04 15:48:32.931 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Color Control: 09CC/1 -> 0000/1, cluster=0300, TID=0C, reports=[AttributeReport [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=7, attributeValue=166]]]

2020-05-04 15:48:32.933 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReportAttributesCommand [Color Control: 09CC/1 -> 0000/1, cluster=0300, TID=0C, reports=[AttributeReport [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=7, attributeValue=166]]] 

2020-05-04 15:48:32.936 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - F0D1B80000069EEF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=F0D1B80000069EEF queueTime=0, state=WAITING, sendCnt=0, command=DefaultResponse [Color Control: 0000/0 -> 09CC/1, cluster=0300, TID=0C, commandIdentifier=10, statusCode=SUCCESS]]

2020-05-04 15:48:32.937 [DEBUG] [rter.ZigBeeConverterColorTemperature] - F0D1B80000069EEF: ZigBee attribute reports ZclAttribute [cluster=Color Control, id=7, name=Color Temperature, dataType=UNSIGNED_16_BIT_INTEGER, lastValue=166, lastReportTime=Mon May 04 15:48:32 CDT 2020, implemented=true]  on endpoint 1

2020-05-04 15:48:32.936 [DEBUG] [.converter.ZigBeeConverterColorColor] - F0D1B80000069EEF: ZigBee attribute reports ZclAttribute [cluster=Color Control, id=7, name=Color Temperature, dataType=UNSIGNED_16_BIT_INTEGER, lastValue=166, lastReportTime=Mon May 04 15:48:32 CDT 2020, implemented=true]

2020-05-04 15:48:32.939 [DEBUG] [transaction.ZigBeeTransactionManager] - 09CC/1: Sending ZigBeeTransaction [ieeeAddress=F0D1B80000069EEF queueTime=2, state=WAITING, sendCnt=0, command=DefaultResponse [Color Control: 0000/0 -> 09CC/1, cluster=0300, TID=0C, commandIdentifier=10, statusCode=SUCCESS]]

2020-05-04 15:48:32.940 [DEBUG] [converter.ZigBeeBaseChannelConverter] - F0D1B80000069EEF: Channel zigbee:device:stick:f0d1b80000069eef:F0D1B80000069EEF_1_colortemperature updated to 11

2020-05-04 15:48:32.941 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-05-04 15:48:32.943 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DefaultResponse [Color Control: 0000/0 -> 09CC/1, cluster=0300, TID=0C, commandIdentifier=10, statusCode=SUCCESS]

2020-05-04 15:48:32.943 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - F0D1B80000069EEF: Updating ZigBee channel state zigbee:device:stick:f0d1b80000069eef:F0D1B80000069EEF_1_colortemperature to 11

2020-05-04 15:48:32.945 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=12, commandId=11]

2020-05-04 15:48:32.947 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=09CC/1, profile=0104, cluster=0300, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=1E, rssi=--, lqi=--, payload=10 0C 0B 0A 00]

2020-05-04 15:48:32.954 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:stick:f0d1b80000069eef


2020-05-04 15:48:32.956 [vent.ItemStateChangedEvent] - BrooklynLight1_ColorTemperature changed from 10 to 11


2020-05-04 15:48:32.956 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Canceling timeout task for thingUID=zigbee:device:stick:f0d1b80000069eef

2020-05-04 15:48:32.963 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=42]

2020-05-04 15:48:32.960 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Scheduling timeout task for thingUID=zigbee:device:stick:f0d1b80000069eef in 14430 seconds

2020-05-04 15:48:32.985 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=09CC, sourceEui=F0D1B80000069EEF, lastHopLqi=255, lastHopRssi=-56, relayList=]

2020-05-04 15:48:33.028 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=2508, apsFrame=EmberApsFrame [profileId=0104, clusterId=0300, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=42], messageTag=0C, status=EMBER_SUCCESS, messageContents=]

2020-05-04 15:48:33.030 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=0C state=RX_ACK

2020-05-04 15:48:33.032 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=0C, state=RX_ACK, outstanding=1

2020-05-04 15:48:33.034 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=F0D1B80000069EEF queueTime=98, state=COMPLETE, sendCnt=1, command=DefaultResponse [Color Control: 0000/0 -> 09CC/1, cluster=0300, TID=0C, commandIdentifier=10, statusCode=SUCCESS]]

2020-05-04 15:48:33.036 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-05-04 15:48:33.038 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - F0D1B80000069EEF: transactionComplete COMPLETE 0

2020-05-04 15:48:33.040 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 0C -> RX_ACK == COMPLETE

2020-05-04 15:48:35.668 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=09CC, sourceEui=F0D1B80000069EEF, lastHopLqi=255, lastHopRssi=-56, relayList=]

2020-05-04 15:48:35.717 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0300, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY], groupId=0, sequence=93], lastHopLqi=255, lastHopRssi=-56, sender=09CC, bindingIndex=255, addressIndex=255, messageContents=08 0D 0A 07 00 21 9E 01]

2020-05-04 15:48:35.721 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=09CC/1, destinationAddress=0000/1, profile=0104, cluster=0300, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=93, rssi=-56, lqi=FF, payload=08 0D 0A 07 00 21 9E 01]

2020-05-04 15:48:35.725 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=13, commandId=10]

2020-05-04 15:48:35.729 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Color Control: 09CC/1 -> 0000/1, cluster=0300, TID=0D, reports=[AttributeReport [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=7, attributeValue=414]]]

2020-05-04 15:48:35.734 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionCommand: ReportAttributesCommand [Color Control: 09CC/1 -> 0000/1, cluster=0300, TID=0D, reports=[AttributeReport [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=7, attributeValue=414]]] 

2020-05-04 15:48:35.738 [DEBUG] [rter.ZigBeeConverterColorTemperature] - F0D1B80000069EEF: ZigBee attribute reports ZclAttribute [cluster=Color Control, id=7, name=Color Temperature, dataType=UNSIGNED_16_BIT_INTEGER, lastValue=414, lastReportTime=Mon May 04 15:48:35 CDT 2020, implemented=true]  on endpoint 1

2020-05-04 15:48:35.738 [DEBUG] [.converter.ZigBeeConverterColorColor] - F0D1B80000069EEF: ZigBee attribute reports ZclAttribute [cluster=Color Control, id=7, name=Color Temperature, dataType=UNSIGNED_16_BIT_INTEGER, lastValue=414, lastReportTime=Mon May 04 15:48:35 CDT 2020, implemented=true]

2020-05-04 15:48:35.742 [DEBUG] [converter.ZigBeeBaseChannelConverter] - F0D1B80000069EEF: Channel zigbee:device:stick:f0d1b80000069eef:F0D1B80000069EEF_1_colortemperature updated to 89

2020-05-04 15:48:35.743 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - F0D1B80000069EEF: Added transaction to queue, len=1, transaction=ZigBeeTransaction [ieeeAddress=F0D1B80000069EEF queueTime=0, state=WAITING, sendCnt=0, command=DefaultResponse [Color Control: 0000/0 -> 09CC/1, cluster=0300, TID=0D, commandIdentifier=10, statusCode=SUCCESS]]

2020-05-04 15:48:35.746 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - F0D1B80000069EEF: Updating ZigBee channel state zigbee:device:stick:f0d1b80000069eef:F0D1B80000069EEF_1_colortemperature to 89

2020-05-04 15:48:35.747 [DEBUG] [transaction.ZigBeeTransactionManager] - 09CC/1: Sending ZigBeeTransaction [ieeeAddress=F0D1B80000069EEF queueTime=4, state=WAITING, sendCnt=0, command=DefaultResponse [Color Control: 0000/0 -> 09CC/1, cluster=0300, TID=0D, commandIdentifier=10, statusCode=SUCCESS]]

2020-05-04 15:48:35.750 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerAdded: 1 outstanding

2020-05-04 15:48:35.753 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Reset timeout for handler with thingUID=zigbee:device:stick:f0d1b80000069eef

2020-05-04 15:48:35.754 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: DefaultResponse [Color Control: 0000/0 -> 09CC/1, cluster=0300, TID=0D, commandIdentifier=10, statusCode=SUCCESS]

2020-05-04 15:48:35.758 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=13, commandId=11]


2020-05-04 15:48:35.760 [vent.ItemStateChangedEvent] - BrooklynLight1_ColorTemperature changed from 11 to 89


2020-05-04 15:48:35.762 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Canceling timeout task for thingUID=zigbee:device:stick:f0d1b80000069eef

2020-05-04 15:48:35.762 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=09CC/1, profile=0104, cluster=0300, addressMode=DEVICE, radius=31, apsSecurity=false, ackRequest=true, apsCounter=1F, rssi=--, lqi=--, payload=10 0D 0B 0A 00]

2020-05-04 15:48:35.764 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - Scheduling timeout task for thingUID=zigbee:device:stick:f0d1b80000069eef in 14430 seconds

2020-05-04 15:48:35.778 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=43]

2020-05-04 15:48:35.800 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=09CC, sourceEui=F0D1B80000069EEF, lastHopLqi=255, lastHopRssi=-56, relayList=]

2020-05-04 15:48:35.844 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=2508, apsFrame=EmberApsFrame [profileId=0104, clusterId=0300, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY, EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY], groupId=0, sequence=43], messageTag=0D, status=EMBER_SUCCESS, messageContents=]

2020-05-04 15:48:35.846 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=0D state=RX_ACK

2020-05-04 15:48:35.848 [DEBUG] [transaction.ZigBeeTransactionManager] - notifyTransactionProgress: TID=0D, state=RX_ACK, outstanding=1

2020-05-04 15:48:35.851 [DEBUG] [transaction.ZigBeeTransactionManager] - Transaction complete: ZigBeeTransaction [ieeeAddress=F0D1B80000069EEF queueTime=109, state=COMPLETE, sendCnt=1, command=DefaultResponse [Color Control: 0000/0 -> 09CC/1, cluster=0300, TID=0D, commandIdentifier=10, statusCode=SUCCESS]]

2020-05-04 15:48:35.852 [DEBUG] [transaction.ZigBeeTransactionManager] - transactionListenerRemoved: 0 outstanding

2020-05-04 15:48:35.854 [DEBUG] [e.transaction.ZigBeeTransactionQueue] - F0D1B80000069EEF: transactionComplete COMPLETE 0

2020-05-04 15:48:35.856 [DEBUG] [zigbee.transaction.ZigBeeTransaction] - Transaction state updated: TID 0D -> RX_ACK == COMPLETE

Nobody is going to bother with that mess until you use code fences.

How to use code fences - Tutorials & Examples - openHAB Community

Should be better now…

I had manually typed in the fences and pasted the log in between… Looked fine in preview but certainly didn’t reflect that after having been posted…

I did try to edit it - removing the fences and typing them in again but that was equally useless… Reading further down in that thread yielded other ways of getting the job done using the icons at the top of the edit window. That worked.

Will be noted for future posts but certainly would be helpful for others new to the forum if it were mentioned at the top of that thread rather than having to dig through the comments. Anyways - I digress…

Perhaps you or someone else can help with this mess now?

1 Like

I unfortunately do not use Zigbee. Perhaps, while you wait, the Zigbee log viewer may help.

https://www.cd-jackson.com/index.php/openhab/zigbee-log-viewer

If we simply look at this from the binding perspective, it looks fine -:

The binding receives the command to go to 89%, and then sends updates as the value goes from 10% to 11% then finally to 89% - as these reports are received from the device (ie the binding doesn’t poll them).

1 Like

Thanks Chris,

So it sounds as if it’s the light itself producing this behavior?

What I mean is that although, visibly, the light changes color instantly, it is rather slow in sending zigbee state updates back to openhab (and does so, perhaps, more than once over the course of a few seconds)?

If that’s the case then there is nothing much that can be done here and it’s time to move on to another device.

Appreciate the help!
-Greg

Well, the light is working as it should from what I see in the log. It is sending reports as required, and the binding is processing them and passing the data through to openHAB.

As mentioned already, the issue is that the UI (or the framework) is updating the state from the command. You click the button to set to 89, and the command is sent, the state is updated to 89, then the light reports that it is 11, so the state is updated to 11, and finally the light reports it is updated to 89 so you reach 89.

In theory I could modify the binding to stop this reporting, but they you will not be happy since if you manually change the bulb state the light will no longer report and then the UI will not be in synch.

The issue is therefore that the framework should not update the state from the command - it should wait for the state to be updated by the binding. I thought there was a setting to do this.

I think changing the polling interval on the device may help?

No - there is no polling.

1 Like

I’ve tried searching quite a bit for a means of disabling framework updates but the only things that seemed applicable were configuring items to veto updates and something about configuring auto-update policies for things.

I did try setting the items to veto updates but that produced no change in behavior.

As far as configuring thing auto update policies, I never did quite figure out how to do that as it didn’t seem to be something that is done in a manually defined thing. Also, I don’t really want to go down that road of manually defining things as it seems OH has been working hard to move people away from doing that.

I’d give it a shot if it were explained how to do so just to see if it works but I’d rather just move on to a solution that doesn’t exhibit such clunkiness. If the light is going to take 3 seconds to report the proper state, that is just too cumbersome to work with.

Appreciate all of your help, but I think I’ll just have to accept that these lights are not the right RGBW solution for my home. I’ll either go back to ZWave or, perhaps, delve into the world of wifi RGBW solutions.

-Greg

How did you do this?

Having read up on this, it is now set in the channel configuration (ie in the binding). I will change this to veto as I think that should resolve the issue, but before I do I’d like to understand what you tried.

Via the PaperUI under Configuration -> Items… In this case editing the Item 'BrooklynLight1_ColorTemperature' provides a dropdown for managing the update behavior. Gives you two choices - “Enforce” and "Veto…

I never tried Enforce, but can definitely say “Veto” seemed ineffective - even after restarting OH and rebooting.

-G

I’ve updated the binding to use veto for command channels. However, I wonder if what you’re seeing is caused by the UI? Maybe, when you click the slider button, the UI sets the value (let’s say to 89). The slider now shows 89, although if at this instance you were to refresh the screen you would see that it’s still 10 as the framework hasn’t updated the state - just the UI has. This command is sent to the binding, and on to the device - as the device changes state, it sends the value to 11 (the UI changes from 89 to 11) and then shortly after the device sends the report saying it is now 89. The UI now changes to 89 as the framework has updated.

Without checking the source of PaperUI, I’m not sure what it does, but I suspect this could be the issue - in general the UI probably should do something different.

Anyway, let’s see if it helps -:

Hey Chris,

I had decided yesterday that I was pretty much done with this path but, since you’ve done the work, I think it’s at least worth giving the changes a try.

I’m still quite new to OH but based on what I’ve learned thus far, it doesn’t seem to me that the issue is with the binding or the UI.

To me the issue seems to be the lights themselves. Any device that takes 3 seconds to report correct state back to OH after receiving a command (particularly when the device itself seemingly responds instantly to the command) is going to be problematic.

I have a handful of other (zwave) devices and none of them exhibit this behavior. Within a few tenths one can see log entries for the command being sent, the expected state updating, and then the actual state update from the device through the binding.

Changing the binding to make the lights “seem” to behave better doesn’t make sense to me on the surface. I’m probably missing a lot of scope here but changing all zigbee channels to veto updates at the binding level seems like taking a sledge hammer to the problem?

Either way, what is the easiest way for me to test your changes? Can I pull down some version of the binding via zzManualInstaller? What version should I be looking for?

Thanks!

I would wait a day or 2 for the newest snapshot. The installer grabs the newest by default, I believe.

The change was just merged into GitHub a minute go so we need to wait for the next snapshot build.

Got it. Appreciate the quick response! Should have some time on Friday to experiment.

-Greg