search

Koenkk / zigbee2mqtt

Zigbee 🐝 to MQTT bridge 🌉, get rid of your proprietary Zigbee bridges 🔨
https://www.zigbee2mqtt.io
GNU General Public License v3.0
12.34k stars 1.69k forks source link

Lots of 'BUSY' reports #24249

Closed corporategoth closed 1 month ago

corporategoth commented 1 month ago

What happened?

I setup an automation in Home Assistant, it's fairly simple.

  1. I have setup 6 groups in Z2M (each for a cluster of 3 smart bulbs).
  2. I setup an automation that, every 2 seconds, will cause ONE of the groups to change the bulb colors (with a 1 second transition).

The effect should be that I slowly see a transition of colors across the 6 groups of bulbs over the course of 10 seconds. This is setup to repeat every 15 seconds.

I am seeing a LOT of BUSY errors:

[2024-10-07 05:17:39] error:    zh:ember: Failed to register group '17' in multicast table with status=INVALID_STATE.
[2024-10-07 05:17:39] error:    zh:ember: Failed to register group '17' in multicast table with status=INVALID_STATE.
[2024-10-07 05:17:40] error:    z2m: Publish 'set' 'brightness' to 'post_6_lights' failed: 'Error: Command 18 genLevelCtrl.moveToLevelWithOnOff({"level":254,"transtime":10}) failed (~x~> [ZCL GROUP groupId=18] Failed to send with status=BUSY.)'
[2024-10-07 05:17:40] error:    z2m: Publish 'set' 'color' to 'post_6_lights' failed: 'Error: Command 18 lightingColorCtrl.moveToColor({"transtime":10,"colorx":14287,"colory":5112}) failed (~x~> [ZCL GROUP groupId=18] Failed to send with status=BUSY.)'
[2024-10-07 05:17:44] error:    z2m: Publish 'set' 'color' to 'post_1_lights' failed: 'Error: Command 13 lightingColorCtrl.moveToColor({"transtime":10,"colorx":14287,"colory":5112}) failed (~x~> [ZCL GROUP groupId=13] Failed to send with status=BUSY.)'
[2024-10-07 05:17:46] error:    z2m: Publish 'set' 'brightness' to 'post_2_lights' failed: 'Error: Command 14 genLevelCtrl.moveToLevelWithOnOff({"level":254,"transtime":10}) failed (~x~> [ZCL GROUP groupId=14] Failed to send with status=BUSY.)'
[2024-10-07 05:17:46] error:    z2m: Publish 'set' 'color' to 'post_2_lights' failed: 'Error: Command 14 lightingColorCtrl.moveToColor({"transtime":10,"colorx":40042,"colory":24576}) failed (~x~> [ZCL GROUP groupId=14] Failed to send with status=BUSY.)'
[2024-10-07 05:17:52] error:    z2m: Publish 'set' 'brightness' to 'post_5_lights' failed: 'Error: Command 17 genLevelCtrl.moveToLevelWithOnOff({"level":254,"transtime":10}) failed (~x~> [ZCL GROUP groupId=17] Failed to send with status=BUSY.)'
[2024-10-07 05:17:52] error:    z2m: Publish 'set' 'color' to 'post_5_lights' failed: 'Error: Command 17 lightingColorCtrl.moveToColor({"transtime":10,"colorx":14287,"colory":5112}) failed (~x~> [ZCL GROUP groupId=17] Failed to send with status=BUSY.)'
[2024-10-07 05:17:54] error:    z2m: Publish 'set' 'brightness' to 'post_6_lights' failed: 'Error: Command 18 genLevelCtrl.moveToLevelWithOnOff({"level":254,"transtime":10}) failed (~x~> [ZCL GROUP groupId=18] Failed to send with status=BUSY.)'
[2024-10-07 05:17:54] error:    z2m: Publish 'set' 'color' to 'post_6_lights' failed: 'Error: Command 18 lightingColorCtrl.moveToColor({"transtime":10,"colorx":40042,"colory":24576}) failed (~x~> [ZCL GROUP groupId=18] Failed to send with status=BUSY.)'
[2024-10-07 05:18:02] error:    z2m: Publish 'set' 'brightness' to 'post_2_lights' failed: 'Error: Command 14 genLevelCtrl.moveToLevelWithOnOff({"level":254,"transtime":10}) failed (~x~> [ZCL GROUP groupId=14] Failed to send with status=BUSY.)'
[2024-10-07 05:18:02] error:    z2m: Publish 'set' 'color' to 'post_2_lights' failed: 'Error: Command 14 lightingColorCtrl.moveToColor({"transtime":10,"colorx":14287,"colory":5112}) failed (~x~> [ZCL GROUP groupId=14] Failed to send with status=BUSY.)'
[2024-10-07 05:18:08] error:    z2m: Publish 'set' 'color' to 'post_5_lights' failed: 'Error: Command 17 lightingColorCtrl.moveToColor({"transtime":10,"colorx":40042,"colory":24576}) failed (~x~> [ZCL GROUP groupId=17] Failed to send with status=BUSY.)'

Also not sure what the INVALID_STATE thing is all about too - as when I look at group 17, it looks fine.

What did you expect to happen?

I expect that each group of 3 bulbs will change color (transitioning over 1 second), a different group every 2 seconds. Without errors.

How to reproduce it (minimal and precise)

Run the automation. It's very reproducible in my environment.

Zigbee2MQTT version

1.40.2

Adapter firmware version

7.4.1

Adapter

ember

Setup

Running in it's own docker env on TrueNAS.

Debug log

[2024-10-07 05:22:06] debug:    z2m:mqtt: Received MQTT message on 'zigbee2mqtt/post_4_lights/set' with data '{"state":"ON","color":{"x":0.218,"y":0.078},"transition":1.0,"brightness":254}'
[2024-10-07 05:22:06] debug:    z2m: Publishing 'set' 'brightness' to 'post_4_lights'
[2024-10-07 05:22:06] debug:    zh:controller:group: Command 16 genLevelCtrl.moveToLevelWithOnOff({"level":254,"transtime":10})
[2024-10-07 05:22:06] debug:    zh:ember: ~~~> [ZCL GROUP apsFrame={"profileId":260,"clusterId":8,"sourceEndpoint":1,"destinationEndpoint":255,"options":4416,"groupId":16,"sequence":0} header={"frameControl":{"reservedBits":0,"frameType":1,"direction":0,"disableDefaultResponse":true,"manufacturerSpecific":false},"transactionSequenceNumber":156,"commandIdentifier":4}]
[2024-10-07 05:22:06] debug:    zh:ember:ezsp: ===> [FRAME: ID=56:"SEND_MULTICAST" Seq=46 Len=26]
[2024-10-07 05:22:06] debug:    zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=3](ackRx=6)
[2024-10-07 05:22:06] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-10-07 05:22:06] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7](ackRx=6 frmTx=7)
[2024-10-07 05:22:06] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=3](frmRx=3) Added to rxQueue
[2024-10-07 05:22:06] debug:    zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4](ackRx=7)
[2024-10-07 05:22:06] debug:    zh:ember:ezsp: <=== [FRAME: ID=56:"SEND_MULTICAST" Seq=46 Len=7]
[2024-10-07 05:22:06] debug:    zh:ember:ezsp: ~~~> [SENT type=MULTICAST apsSequence=93 messageTag=99 status=BUSY]
[2024-10-07 05:22:06] debug:    zh:controller:group: Error: Command 16 genLevelCtrl.moveToLevelWithOnOff({"level":254,"transtime":10}) failed (~x~> [ZCL GROUP groupId=16] Failed to send with status=BUSY.)
    at /app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:2151:23
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
    at runNextTicks (node:internal/process/task_queues:64:3)
    at processImmediate (node:internal/timers:447:9)
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:36:20)
    at EmberAdapter.sendZclFrameToGroup (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:2135:16)
    at Group.command (/app/node_modules/zigbee-herdsman/src/controller/model/group.ts:288:13)
    at Object.convertSet (/app/node_modules/zigbee-herdsman-converters/src/converters/toZigbee.ts:1168:13)
    at Publish.onMQTTMessage (/app/lib/extension/publish.ts:306:36)
    at EventEmitter.wrappedCallback (/app/lib/eventBus.ts:206:17)
[2024-10-07 05:22:06] error:    z2m: Publish 'set' 'brightness' to 'post_4_lights' failed: 'Error: Command 16 genLevelCtrl.moveToLevelWithOnOff({"level":254,"transtime":10}) failed (~x~> [ZCL GROUP groupId=16] Failed to send with status=BUSY.)'
[2024-10-07 05:22:06] debug:    z2m: Error: Command 16 genLevelCtrl.moveToLevelWithOnOff({"level":254,"transtime":10}) failed (~x~> [ZCL GROUP groupId=16] Failed to send with status=BUSY.)
    at /app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:2151:23
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
    at runNextTicks (node:internal/process/task_queues:64:3)
    at processImmediate (node:internal/timers:447:9)
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:36:20)
    at EmberAdapter.sendZclFrameToGroup (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:2135:16)
    at Group.command (/app/node_modules/zigbee-herdsman/src/controller/model/group.ts:288:13)
    at Object.convertSet (/app/node_modules/zigbee-herdsman-converters/src/converters/toZigbee.ts:1168:13)
    at Publish.onMQTTMessage (/app/lib/extension/publish.ts:306:36)
    at EventEmitter.wrappedCallback (/app/lib/eventBus.ts:206:17)
[2024-10-07 05:22:06] debug:    z2m: Publishing 'set' 'color' to 'post_4_lights'
[2024-10-07 05:22:06] debug:    zh:controller:group: Command 16 lightingColorCtrl.moveToColor({"transtime":10,"colorx":14287,"colory":5112})
[2024-10-07 05:22:06] debug:    zh:ember: ~~~> [ZCL GROUP apsFrame={"profileId":260,"clusterId":768,"sourceEndpoint":1,"destinationEndpoint":255,"options":4416,"groupId":16,"sequence":0} header={"frameControl":{"reservedBits":0,"frameType":1,"direction":0,"disableDefaultResponse":true,"manufacturerSpecific":false},"transactionSequenceNumber":157,"commandIdentifier":7}]
[2024-10-07 05:22:06] debug:    zh:ember:ezsp: ===> [FRAME: ID=56:"SEND_MULTICAST" Seq=47 Len=29]
[2024-10-07 05:22:06] debug:    zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=4](ackRx=7)
[2024-10-07 05:22:06] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-10-07 05:22:06] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0](ackRx=7 frmTx=0)
[2024-10-07 05:22:06] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=4](frmRx=4) Added to rxQueue
[2024-10-07 05:22:06] debug:    zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5](ackRx=0)
[2024-10-07 05:22:06] debug:    zh:ember:ezsp: <=== [FRAME: ID=56:"SEND_MULTICAST" Seq=47 Len=7]
[2024-10-07 05:22:06] debug:    zh:ember:ezsp: ~~~> [SENT type=MULTICAST apsSequence=94 messageTag=100 status=BUSY]
[2024-10-07 05:22:06] debug:    zh:controller:group: Error: Command 16 lightingColorCtrl.moveToColor({"transtime":10,"colorx":14287,"colory":5112}) failed (~x~> [ZCL GROUP groupId=16] Failed to send with status=BUSY.)
    at /app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:2151:23
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
    at runNextTicks (node:internal/process/task_queues:64:3)
    at processImmediate (node:internal/timers:447:9)
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:36:20)
    at EmberAdapter.sendZclFrameToGroup (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:2135:16)
    at Group.command (/app/node_modules/zigbee-herdsman/src/controller/model/group.ts:288:13)
    at Object.convertSet (/app/node_modules/zigbee-herdsman-converters/src/converters/toZigbee.ts:148:13)
    at Object.convertSet (/app/node_modules/zigbee-herdsman-converters/src/converters/toZigbee.ts:1235:32)
    at Publish.onMQTTMessage (/app/lib/extension/publish.ts:306:36)
[2024-10-07 05:22:06] error:    z2m: Publish 'set' 'color' to 'post_4_lights' failed: 'Error: Command 16 lightingColorCtrl.moveToColor({"transtime":10,"colorx":14287,"colory":5112}) failed (~x~> [ZCL GROUP groupId=16] Failed to send with status=BUSY.)'
[2024-10-07 05:22:06] debug:    z2m: Error: Command 16 lightingColorCtrl.moveToColor({"transtime":10,"colorx":14287,"colory":5112}) failed (~x~> [ZCL GROUP groupId=16] Failed to send with status=BUSY.)
    at /app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:2151:23
    at processTicksAndRejections (node:internal/process/task_queues:95:5)
    at runNextTicks (node:internal/process/task_queues:64:3)
    at processImmediate (node:internal/timers:447:9)
    at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:36:20)
    at EmberAdapter.sendZclFrameToGroup (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:2135:16)
    at Group.command (/app/node_modules/zigbee-herdsman/src/controller/model/group.ts:288:13)
    at Object.convertSet (/app/node_modules/zigbee-herdsman-converters/src/converters/toZigbee.ts:148:13)
    at Object.convertSet (/app/node_modules/zigbee-herdsman-converters/src/converters/toZigbee.ts:1235:32)
    at Publish.onMQTTMessage (/app/lib/extension/publish.ts:306:36)
[2024-10-07 05:22:06] debug:    z2m: Publishing 'set' 'transition' to 'post_4_lights'
[2024-10-07 05:22:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-10-07 05:22:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0](ackRx=0 frmTx=0)
[2024-10-07 05:22:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=5](frmRx=5) Added to rxQueue
[2024-10-07 05:22:07] debug:    zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6](ackRx=0)
[2024-10-07 05:22:07] debug:    zh:ember:ezsp: <=== [CBFRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=47 Len=37]
[2024-10-07 05:22:07] debug:    zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":1,"destinationEndpoint":1,"options":64,"groupId":0,"sequence":125}], [packetInfo:{"senderShortId":10208,"senderLongId":"0xFFFFFFFFFFFFFFFF","bindingIndex":255,"addressIndex":255,"lastHopLqi":172,"lastHopRssi":-57,"lastHopTimestamp":0}], [messageContents=011301006011d18016000000]
[2024-10-07 05:22:07] debug:    zh:controller: Received payload: clusterID=25, address=10208, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=172, frame={"header":{"frameControl":{"frameType":1,"manufacturerSpecific":false,"direction":0,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":19,"commandIdentifier":1},"payload":{"fieldControl":0,"manufacturerCode":4448,"imageType":32977,"fileVersion":22},"command":{"ID":1,"response":2,"parameters":[{"name":"fieldControl","type":32},{"name":"manufacturerCode","type":33},{"name":"imageType","type":33},{"name":"fileVersion","type":35}],"name":"queryNextImageRequest"}}
[2024-10-07 05:22:07] debug:    z2m: Received Zigbee message from 'Post 4 Light - Medium', type 'commandQueryNextImageRequest', cluster 'genOta', data '{"fieldControl":0,"fileVersion":22,"imageType":32977,"manufacturerCode":4448}' from endpoint 1 with groupID 0
[2024-10-07 05:22:07] info:     z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Post 4 Light - Medium', payload '{"brightness":254,"color":{"x":0.611,"y":0.375},"color_mode":"xy","color_temp":500,"energy":1.52,"last_seen":"2024-10-07T05:22:07+00:00","level_config":{"on_level":"previous"},"linkquality":172,"power":0.2,"state":"ON","update":{"installed_version":22,"latest_version":22,"state":"idle"},"update_available":null}'
[2024-10-07 05:22:07] debug:    z2m: Device 'Post 4 Light - Medium' requested OTA
[2024-10-07 05:22:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-10-07 05:22:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0](ackRx=0 frmTx=0)
[2024-10-07 05:22:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=6](frmRx=6) Added to rxQueue
[2024-10-07 05:22:07] debug:    zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7](ackRx=0)
[2024-10-07 05:22:07] debug:    zh:ember:ezsp: <=== [CBFRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=47 Len=20]
[2024-10-07 05:22:07] debug:    zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=16982], [sourceEui=0x6c5cb1fffe5e7ca7], [lastHopLqi=192], [lastHopRssi=-52], [relayCount=1], [relayList=24915]
[2024-10-07 05:22:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-10-07 05:22:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0](ackRx=0 frmTx=0)
[2024-10-07 05:22:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7](frmRx=7) Added to rxQueue
[2024-10-07 05:22:07] debug:    zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0](ackRx=0)
[2024-10-07 05:22:07] debug:    zh:ember:ezsp: <=== [CBFRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=47 Len=33]
[2024-10-07 05:22:07] debug:    zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":2820,"sourceEndpoint":1,"destinationEndpoint":1,"options":64,"groupId":0,"sequence":139}], [packetInfo:{"senderShortId":51526,"senderLongId":"0xFFFFFFFFFFFFFFFF","bindingIndex":255,"addressIndex":255,"lastHopLqi":140,"lastHopRssi":-65,"lastHopTimestamp":0}], [messageContents=18010a0b0529a600]
[2024-10-07 05:22:07] debug:    zh:controller: Received payload: clusterID=2820, address=51526, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=140, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":1,"commandIdentifier":10},"payload":[{"attrId":1291,"dataType":41,"attrData":166}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-10-07 05:22:07] debug:    z2m: Received Zigbee message from 'Basement Door Light', type 'attributeReport', cluster 'haElectricalMeasurement', data '{"activePower":166}' from endpoint 1 with groupID 0
[2024-10-07 05:22:07] info:     z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Basement Door Light', payload '{"activeEnergyReports":250,"activePowerReports":25,"autoTimerOff":0,"auxSwitchUniqueScenes":null,"bindingOffToOnSyncLevel":null,"brightness":254,"brightnessLevelForDoubleTapDown":null,"brightnessLevelForDoubleTapUp":null,"buttonDelay":"100ms","defaultLed1ColorWhenOff":255,"defaultLed1ColorWhenOn":255,"defaultLed1IntensityWhenOff":101,"defaultLed1IntensityWhenOn":101,"defaultLed2ColorWhenOff":255,"defaultLed2ColorWhenOn":255,"defaultLed2IntensityWhenOff":101,"defaultLed2IntensityWhenOn":101,"defaultLed3ColorWhenOff":255,"defaultLed3ColorWhenOn":255,"defaultLed3IntensityWhenOff":101,"defaultLed3IntensityWhenOn":101,"defaultLed4ColorWhenOff":255,"defaultLed4ColorWhenOn":255,"defaultLed4IntensityWhenOff":101,"defaultLed4IntensityWhenOn":101,"defaultLed5ColorWhenOff":255,"defaultLed5ColorWhenOn":255,"defaultLed5IntensityWhenOff":101,"defaultLed5IntensityWhenOn":101,"defaultLed6ColorWhenOff":255,"defaultLed6ColorWhenOn":255,"defaultLed6IntensityWhenOff":101,"defaultLed6IntensityWhenOn":101,"defaultLed7ColorWhenOff":255,"defaultLed7ColorWhenOn":255,"defaultLed7IntensityWhenOff":101,"defaultLed7IntensityWhenOn":101,"defaultLevelLocal":255,"defaultLevelRemote":255,"deviceBindNumber":null,"dimmingSpeedDownLocal":10,"dimmingSpeedDownRemote":0,"dimmingSpeedUpLocal":25,"dimmingSpeedUpRemote":0,"doubleTapClearNotifications":"Disabled","doubleTapDownToParam56":"Disabled","doubleTapUpForFullBrightness":"Button Press Event + Set Load to 100%","doubleTapUpToParam55":"Disabled","energy":251.95,"fanControlMode":null,"fanLedLevelType":null,"firmwareUpdateInProgressIndicator":"Enabled","highLevelForFanControlMode":null,"higherOutputInNonNeutral":null,"individual_led_effect":null,"internalTemperature":null,"invertSwitch":"No","last_seen":"2024-10-07T05:22:07+00:00","ledBarScaling":null,"ledColorForFanControlMode":null,"ledColorWhenOff":null,"ledColorWhenOn":null,"ledIntensityWhenOff":1,"ledIntensityWhenOn":33,"led_effect":null,"linkquality":140,"loadLevelIndicatorTimeout":"Stay On","localProtection":"Disabled","lowLevelForFanControlMode":null,"maximumLevel":null,"mediumLevelForFanControlMode":null,"minimumLevel":null,"onOffLedMode":"All","outputMode":"On/Off","overheat":null,"periodicPowerAndEnergyReports":300,"power":16.6,"powerType":null,"quickStartLevel":null,"quickStartTime":null,"rampRateOffToOnLocal":5,"rampRateOffToOnRemote":5,"rampRateOnToOffLocal":10,"rampRateOnToOffRemote":10,"relayClick":"Disabled (Click Sound On)","remoteProtection":null,"singleTapBehavior":null,"smartBulbMode":null,"state":"ON","stateAfterPowerRestored":0,"switchType":null,"update":{"installed_version":16908818,"latest_version":16908818,"state":"idle"},"update_available":null}'
[2024-10-07 05:22:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-10-07 05:22:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0](ackRx=0 frmTx=0)
[2024-10-07 05:22:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=0](frmRx=0) Added to rxQueue
[2024-10-07 05:22:07] debug:    zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1](ackRx=0)
[2024-10-07 05:22:07] debug:    zh:ember:ezsp: <=== [CBFRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=47 Len=37]
[2024-10-07 05:22:07] debug:    zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":1,"destinationEndpoint":1,"options":64,"groupId":0,"sequence":139}], [packetInfo:{"senderShortId":11290,"senderLongId":"0xFFFFFFFFFFFFFFFF","bindingIndex":255,"addressIndex":255,"lastHopLqi":136,"lastHopRssi":-66,"lastHopTimestamp":0}], [messageContents=114101002f12010112020201]
[2024-10-07 05:22:07] debug:    zh:controller: Received payload: clusterID=25, address=11290, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=136, frame={"header":{"frameControl":{"frameType":1,"manufacturerSpecific":false,"direction":0,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":65,"commandIdentifier":1},"payload":{"fieldControl":0,"manufacturerCode":4655,"imageType":257,"fileVersion":16908818},"command":{"ID":1,"response":2,"parameters":[{"name":"fieldControl","type":32},{"name":"manufacturerCode","type":33},{"name":"imageType","type":33},{"name":"fileVersion","type":35}],"name":"queryNextImageRequest"}}
corporategoth commented 1 month ago

Updated firmware to 8.0.2, and the errors disappeared.

IsaacWG commented 1 month ago

Thanks @corporategoth! I was having similar issues with Philips Hue light bulbs in groups and the experimental 8.0.2 firmware helped me as well with my Sonoff ZBDongle-E adapter. I still get some Failed to send with status=BUSY errors when sending commands to the lights too quickly, but it is at least much more reasonable and it seems to recover faster.

rbnet commented 1 week ago

@corporategoth @IsaacWG Sorry for the trivial question, but where can I download firmware 8.0.2 for the SonOFF Dongle-E from? I have the same problem with groups of Philips Hue lamps.

corporategoth commented 1 week ago

@rbnet https://github.com/Nerivec/silabs-firmware-builder Make sure you get the coordinator (ncp) not router firmware.

rbnet commented 1 week ago

The update to firmware 8.0.2 completely fixed the problem. Thank you.