Koenkk / zigbee2mqtt

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

Broadcasts failing on ember after migration #22453

Closed julien-billaud closed 3 weeks ago

julien-billaud commented 5 months ago

What happened?

While I've never been facing any issues for more than a year with the Sonoff Dongle-e + ezsp driver, I've tried to change the driver to ember, but nothing is working (tried multiple time) but sometime losing all the devices, sometime they are still there but impossible to interact with them, and pairing is never working. (for now I returned to the ezsp driver). I'm not noticing much error in the log (only the broadcast error reported here https://github.com/Koenkk/zigbee2mqtt/issues/22445)

I've tried the exact same configuration on a regular x86 computer running debian (using the same zigbee dongle) and didn't face any issue which seems to be a linked with the Raspberry pi 4

What did you expect to happen?

No response

How to reproduce it (minimal and precise)

switch from eszp to ember driver

Zigbee2MQTT version

1.37.0

Adapter firmware version

7.4.2.0 build 0

Adapter

Sonoff dongle-e

Setup

Raspberry pi 4 using docker image

Debug log

No response

Ricc68 commented 4 months ago

I have installed firmware 7.4.3 on the EZDongle-E. With 7.4.2 I had one broadcast error every 10 minutes. With 7.4.3 I have had just one broadcast error since z2m started 90 minutes ago. I see a clear improvement here: no other change except the dongle firmware. I'll see tomorrow if the frequency of broadcast errors remains so low.

supaeasy commented 4 months ago

Could you point me to 7.4.3? All I found is 7.4.2

Nerivec commented 4 months ago

@supaeasy https://github.com/darkxst/silabs-firmware-builder/tree/4.4.3/firmware_builds

Ricc68 commented 4 months ago

I confirm that in more than 10 hours since z2m started I had just that single broadcast error at 90 min from start, which may still indicate a glitch but I would say updating the dongle fw to 7.4.3 solved the issue.

SubZero77 commented 4 months ago

I have the same problem on OrangePi 5 and SONOFF Dongle-E Plus V2. The error started appearing recently. Adapter firmware NCP 7.4.3 (ncp-uart-hw-v7.4.3.0-zbdonglee-230400.gbl) Debian GNU/Linux 12 (bookworm) Docker 26.1.1 core-2024.5.3 supervisor-2024.05.1 stable

Logs ``` [09:12:45] INFO: Starting Zigbee2MQTT... [2024-05-16 09:12:47] info: z2m: Logging to console, file (filename: log.log) [2024-05-16 09:12:47] info: z2m: Starting Zigbee2MQTT version 1.37.1 (commit #unknown) [2024-05-16 09:12:47] info: z2m: Starting zigbee-herdsman (0.46.6) [2024-05-16 09:12:48] info: zh:ember: ======== Ember Adapter Starting ======== [2024-05-16 09:12:48] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-05-16 09:12:48] info: zh:ember:uart:ash: ======== ASH NCP reset ======== [2024-05-16 09:12:48] info: zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control. [2024-05-16 09:12:48] info: zh:ember:uart:ash: Serial port opened [2024-05-16 09:12:48] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-05-16 09:12:49] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-05-16 09:12:49] info: zh:ember:uart:ash: ======== ASH started ======== [2024-05-16 09:12:49] info: zh:ember:ezsp: ======== EZSP started ======== [2024-05-16 09:12:49] info: zh:ember: [STACK STATUS] Network up. [2024-05-16 09:12:49] info: zh:ember: [INIT TC] NCP network matches config. [2024-05-16 09:12:49] info: zh:ember: [CONCENTRATOR] Started source route discovery. 1248ms until next broadcast. [2024-05-16 09:12:49] info: z2m: zigbee-herdsman started (resumed) [2024-05-16 09:12:49] info: z2m: Coordinator firmware version: '{"meta":{"build":0,"ezsp":13,"major":7,"minor":4,"patch":3,"revision":"7.4.3 [GA]","special":0,"type":170},"type":"EmberZNet"}' [2024-05-16 09:12:49] info: z2m: Currently 21 devices are joined: [2024-05-16 09:12:49] info: z2m: hot_water_valve (0x70b3d52b600242ac): ZN231392 - TuYa Smart water/gas valve (Router) [2024-05-16 09:12:49] info: z2m: cold_water_valve (0x70b3d52b600245e4): ZN231392 - TuYa Smart water/gas valve (Router) [2024-05-16 09:12:49] info: z2m: bathroom_water_leak_1 (0x00158d0008e0380b): SJCGQ11LM - Aqara Water leak sensor (EndDevice) [2024-05-16 09:12:49] info: z2m: bathroom_water_leak_2 (0x00158d0008dfb8d1): SJCGQ11LM - Aqara Water leak sensor (EndDevice) [2024-05-16 09:12:49] info: z2m: big_room_weather_1 (0x00158d0006fab9c2): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-16 09:12:49] info: z2m: bathroom_weather_1 (0x00158d000759b371): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-16 09:12:49] info: z2m: kitchen_weather_1 (0x00158d00073a14ff): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-16 09:12:49] info: z2m: big_room_motion_1 (0x54ef44100052bbc7): RTCGQ14LM - Aqara Motion sensor P1 (EndDevice) [2024-05-16 09:12:49] info: z2m: corridor_opening_1 (0x54ef44100044b12d): MCCGQ13LM - Aqara Door and window sensor P1 (EndDevice) [2024-05-16 09:12:49] info: z2m: balcony_weather_1 (0x00158d00073a1815): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-16 09:12:49] info: z2m: toilet_weather_1 (0x00158d000a81f3b4): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-16 09:12:49] info: z2m: kitchen_water_leak_1 (0x00158d0008dff1a0): SJCGQ11LM - Aqara Water leak sensor (EndDevice) [2024-05-16 09:12:49] info: z2m: kitchen_water_leak_2 (0x00158d0008e0ad11): SJCGQ11LM - Aqara Water leak sensor (EndDevice) [2024-05-16 09:12:49] info: z2m: corridor_motion_1 (0x54ef44100052cdbf): RTCGQ14LM - Aqara Motion sensor P1 (EndDevice) [2024-05-16 09:12:49] info: z2m: corridor_motion_2 (0x54ef44100052cd9b): RTCGQ14LM - Aqara Motion sensor P1 (EndDevice) [2024-05-16 09:12:49] info: z2m: kitchen_motion_1 (0x54ef44100052bc28): RTCGQ14LM - Aqara Motion sensor P1 (EndDevice) [2024-05-16 09:12:49] info: z2m: kitchen_smoke_1 (0x54ef441000711e13): JY-GZ-01AQ - Aqara Smart smoke detector (EndDevice) [2024-05-16 09:12:49] info: z2m: balcony_motion_1 (0x54ef44100052d0b3): RTCGQ14LM - Aqara Motion sensor P1 (EndDevice) [2024-05-16 09:12:49] info: z2m: balcony_dimmer_1 (0xa4c138467f6be91f): TS0601_dimmer_1 - TuYa 1 gang smart dimmer (Router) [2024-05-16 09:12:49] info: z2m: small_room_weather_1 (0x00158d000a81f3e0): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-16 09:12:49] info: z2m: small_room_smoke_1 (0x54ef44100062e4c9): JY-GZ-01AQ - Aqara Smart smoke detector (EndDevice) [2024-05-16 09:12:49] info: z2m: Zigbee: disabling joining new devices. [2024-05-16 09:12:49] info: z2m: Connecting to MQTT server at mqtt://core-mosquitto:1883 [2024-05-16 09:12:49] info: z2m: Connected to MQTT server [2024-05-16 09:12:49] info: z2m: Started frontend on port 8099 [2024-05-16 09:12:50] info: z2m: Zigbee2MQTT started! [2024-05-16 09:12:50] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":34} messageTag=255] [2024-05-16 09:12:50] error: zh:ember: Delivery of BROADCAST failed for "65532" [apsFrame={"profileId":0,"clusterId":54,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":35} messageTag=1] [2024-05-16 09:13:04] error: zh:ember: Delivery of BROADCAST failed for "65532" [apsFrame={"profileId":0,"clusterId":31,"sourceEndpoint":0,"destinationEndpoint":0,"options":0,"groupId":0,"sequence":0} messageTag=255] ```
SubZero77 commented 4 months ago

New info... my serial config was: port: /dev/ttyACM0 adapter: ember baudrate: 230400 Аfter I removed the "baudrate: 230400" everything started to work. But now there is such an error ;)

Logs ``` [2024-05-16 21:29:43] info: z2m: Logging to console, file (filename: log.log) [2024-05-16 21:29:43] info: z2m: Starting Zigbee2MQTT version 1.37.1 (commit #unknown) [2024-05-16 21:29:43] info: z2m: Starting zigbee-herdsman (0.46.6) [2024-05-16 21:29:43] info: zh:ember: ======== Ember Adapter Starting ======== [2024-05-16 21:29:43] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-05-16 21:29:43] info: zh:ember:uart:ash: ======== ASH NCP reset ======== [2024-05-16 21:29:43] info: zh:ember:uart:ash: Serial port opened [2024-05-16 21:29:43] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-05-16 21:29:43] error: zh:ember:uart:ash: Received frame with CRC error ```

But all devices can now connect. The strange thing is that now when I put this line back, everything still continues to work.

Nerivec commented 4 months ago

@SubZero77 Did you by any chance unplug the adapter and plug it back in around that same time? If you have a 230400 baudrate, then you definitely need to put 230400 in z2m config. It that doesn't match, it will definitely create troubles. If you aren't 100% sure what baudrate firmware you flashed last, then you should flash the firmware again, and this time take note of what baudrate it has to match it in z2m config. (115200 is the more common one, far more tested since most people use it.)

PS: The CRC error on start is common enough, just noise on port opening, wouldn't worry about it as long as it starts after that.

Ricc68 commented 4 months ago

Just an update on the statistics with firmware 7.4.3: I am at 1~2 broadcast errors per day.

@Nerivec any comment on these few remaining errors?

SubZero77 commented 4 months ago

@SubZero77 Did you by any chance unplug the adapter and plug it back in around that same time?

@Nerivec no, I did not turn off Dongle-E and did not turn off the power from the Orange Ps 5 either, but I did reboot through the Developer Panel -> Restart HA. I definitely flashed the 230400 (file ncp-uart-hw-v7.4.3.0-zbdonglee-230400.gbl) I looked at the configuration file /homeassistant/zigbee2mqtt/configuration.yml and it says this: serial: port: /dev/ttyACM0 adapter: amber baudrate: 230400 rts cts: true So my deleting line 230400 in and adding it back in the Zigbee2MQTT interface didn't change anything. Another thing I did before everything started working was to remove one Zigbee dimmer that didn't want to work in any way https://www.zigbee2mqtt.io/devices/TS0601_dimmer_1.html p.s. I found the reason!!! I just brought this dimmer back and everything stopped working again and the "Delivery of BROADCAST failed" errors appeared. When adding it wrote about the difference in versions: warning: zh:ember: [ZDO] Node descriptor for "2294" reports device is only compliant to revision "21" of the ZigBee specification (current revision: 23). After removing this dimmer, everything worked. Do I need to write somewhere else about this problem with this dimmer?

Logs ``` [2024-05-17 08:49:00] info: z2m: Zigbee: allowing new devices to join. [2024-05-17 08:49:00] info: zh:ember: [STACK STATUS] Network opened. [2024-05-17 08:49:14] info: zh:controller: Interview for '0xa4c138467f6be91f' started [2024-05-17 08:49:14] info: z2m: Device '0xa4c138467f6be91f' joined [2024-05-17 08:49:14] info: z2m: Starting interview of '0xa4c138467f6be91f' [2024-05-17 08:49:14] warning: zh:ember: [ZDO] Node descriptor for "2294" reports device is only compliant to revision "21" of the ZigBee specification (current revision: 23). [2024-05-17 08:49:14] info: zh:controller: Succesfully interviewed '0xa4c138467f6be91f' [2024-05-17 08:49:14] info: z2m: Successfully interviewed '0xa4c138467f6be91f', device has successfully been paired [2024-05-17 08:49:14] info: z2m: Device '0xa4c138467f6be91f' is supported, identified as: TuYa 1 gang smart dimmer (TS0601_dimmer_1) [2024-05-17 08:49:14] info: z2m: Configuring '0xa4c138467f6be91f' [2024-05-17 08:49:14] info: z2m: Successfully configured '0xa4c138467f6be91f' [2024-05-17 08:51:41] info: z2m: Starting network scan (includeRoutes 'false') [2024-05-17 08:51:47] info: z2m: Network scan finished [2024-05-17 08:53:14] info: zh:ember: [STACK STATUS] Network closed. [2024-05-17 08:53:40] info: z2m: Disconnecting from MQTT server [2024-05-17 08:53:40] info: z2m: Stopping zigbee-herdsman... [2024-05-17 08:53:40] info: zh:controller: Wrote coordinator backup to '/config/zigbee2mqtt/coordinator_backup.json' [2024-05-17 08:53:40] info: zh:ember:uart:ash: ASH COUNTERS since last clear: [2024-05-17 08:53:40] info: zh:ember:uart:ash: Total frames: RX=1766, TX=1861 [2024-05-17 08:53:40] info: zh:ember:uart:ash: Cancelled : RX=0, TX=0 [2024-05-17 08:53:40] info: zh:ember:uart:ash: DATA frames : RX=1766, TX=102 [2024-05-17 08:53:40] info: zh:ember:uart:ash: DATA bytes : RX=59837, TX=2511 [2024-05-17 08:53:40] info: zh:ember:uart:ash: Retry frames: RX=0, TX=0 [2024-05-17 08:53:40] info: zh:ember:uart:ash: ACK frames : RX=0, TX=1759 [2024-05-17 08:53:40] info: zh:ember:uart:ash: NAK frames : RX=0, TX=0 [2024-05-17 08:53:40] info: zh:ember:uart:ash: nRdy frames : RX=0, TX=0 [2024-05-17 08:53:40] info: zh:ember:uart:ash: CRC errors : RX=0 [2024-05-17 08:53:40] info: zh:ember:uart:ash: Comm errors : RX=0 [2024-05-17 08:53:40] info: zh:ember:uart:ash: Length < minimum: RX=0 [2024-05-17 08:53:40] info: zh:ember:uart:ash: Length > maximum: RX=0 [2024-05-17 08:53:40] info: zh:ember:uart:ash: Bad controls : RX=0 [2024-05-17 08:53:40] info: zh:ember:uart:ash: Bad lengths : RX=0 [2024-05-17 08:53:40] info: zh:ember:uart:ash: Bad ACK numbers : RX=0 [2024-05-17 08:53:40] info: zh:ember:uart:ash: Out of buffers : RX=0 [2024-05-17 08:53:40] info: zh:ember:uart:ash: Retry dupes : RX=0 [2024-05-17 08:53:40] info: zh:ember:uart:ash: Out of sequence : RX=0 [2024-05-17 08:53:40] info: zh:ember:uart:ash: ACK timeouts : RX=0 [2024-05-17 08:53:40] info: zh:ember:uart:ash: Port closed. Error? no [2024-05-17 08:53:40] info: zh:ember:uart:ash: ======== ASH stopped ======== [2024-05-17 08:53:40] info: zh:ember:ezsp: ======== EZSP stopped ======== [2024-05-17 08:53:40] info: zh:ember: ======== Ember Adapter Stopped ======== [2024-05-17 08:53:40] info: z2m: Stopped zigbee-herdsman [2024-05-17 08:53:40] info: z2m: Stopped Zigbee2MQTT [08:53:41] INFO: Preparing to start... [08:53:41] INFO: Socat not enabled [08:53:42] INFO: Starting Zigbee2MQTT... [2024-05-17 08:53:45] info: z2m: Logging to console, file (filename: log.log) [2024-05-17 08:53:45] info: z2m: Starting Zigbee2MQTT version 1.37.1 (commit #unknown) [2024-05-17 08:53:45] info: z2m: Starting zigbee-herdsman (0.46.6) [2024-05-17 08:53:45] info: zh:ember: ======== Ember Adapter Starting ======== [2024-05-17 08:53:45] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-05-17 08:53:45] info: zh:ember:uart:ash: ======== ASH NCP reset ======== [2024-05-17 08:53:45] info: zh:ember:uart:ash: Serial port opened [2024-05-17 08:53:45] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-05-17 08:53:45] error: zh:ember:uart:ash: Received frame with CRC error [2024-05-17 08:53:46] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-05-17 08:53:46] info: zh:ember:uart:ash: ======== ASH started ======== [2024-05-17 08:53:46] info: zh:ember:ezsp: ======== EZSP started ======== [2024-05-17 08:53:46] info: zh:ember: [STACK STATUS] Network up. [2024-05-17 08:53:46] info: zh:ember: [INIT TC] NCP network matches config. [2024-05-17 08:53:46] info: zh:ember: [CONCENTRATOR] Started source route discovery. 1248ms until next broadcast. [2024-05-17 08:53:46] info: z2m: zigbee-herdsman started (resumed) [2024-05-17 08:53:46] info: z2m: Coordinator firmware version: '{"meta":{"build":0,"ezsp":13,"major":7,"minor":4,"patch":3,"revision":"7.4.3 [GA]","special":0,"type":170},"type":"EmberZNet"}' [2024-05-17 08:53:46] info: z2m: Currently 22 devices are joined: [2024-05-17 08:53:46] info: z2m: hot_water_valve (0x70b3d52b600242ac): ZN231392 - TuYa Smart water/gas valve (Router) [2024-05-17 08:53:46] info: z2m: cold_water_valve (0x70b3d52b600245e4): ZN231392 - TuYa Smart water/gas valve (Router) [2024-05-17 08:53:46] info: z2m: bathroom_water_leak_1 (0x00158d0008e0380b): SJCGQ11LM - Aqara Water leak sensor (EndDevice) [2024-05-17 08:53:46] info: z2m: bathroom_water_leak_2 (0x00158d0008dfb8d1): SJCGQ11LM - Aqara Water leak sensor (EndDevice) [2024-05-17 08:53:46] info: z2m: big_room_weather_1 (0x00158d0006fab9c2): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-17 08:53:46] info: z2m: bathroom_weather_1 (0x00158d000759b371): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-17 08:53:46] info: z2m: kitchen_weather_1 (0x00158d00073a14ff): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-17 08:53:46] info: z2m: big_room_motion_1 (0x54ef44100052bbc7): RTCGQ14LM - Aqara Motion sensor P1 (EndDevice) [2024-05-17 08:53:46] info: z2m: corridor_opening_1 (0x54ef44100044b12d): MCCGQ13LM - Aqara Door and window sensor P1 (EndDevice) [2024-05-17 08:53:46] info: z2m: balcony_weather_1 (0x00158d00073a1815): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-17 08:53:46] info: z2m: toilet_weather_1 (0x00158d000a81f3b4): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-17 08:53:46] info: z2m: kitchen_water_leak_1 (0x00158d0008dff1a0): SJCGQ11LM - Aqara Water leak sensor (EndDevice) [2024-05-17 08:53:46] info: z2m: kitchen_water_leak_2 (0x00158d0008e0ad11): SJCGQ11LM - Aqara Water leak sensor (EndDevice) [2024-05-17 08:53:46] info: z2m: corridor_motion_1 (0x54ef44100052cdbf): RTCGQ14LM - Aqara Motion sensor P1 (EndDevice) [2024-05-17 08:53:46] info: z2m: corridor_motion_2 (0x54ef44100052cd9b): RTCGQ14LM - Aqara Motion sensor P1 (EndDevice) [2024-05-17 08:53:46] info: z2m: kitchen_motion_1 (0x54ef44100052bc28): RTCGQ14LM - Aqara Motion sensor P1 (EndDevice) [2024-05-17 08:53:46] info: z2m: kitchen_smoke_1 (0x54ef441000711e13): JY-GZ-01AQ - Aqara Smart smoke detector (EndDevice) [2024-05-17 08:53:46] info: z2m: balcony_motion_1 (0x54ef44100052d0b3): RTCGQ14LM - Aqara Motion sensor P1 (EndDevice) [2024-05-17 08:53:46] info: z2m: big_room_smoke_1 (0x54ef44100062f13d): JY-GZ-01AQ - Aqara Smart smoke detector (EndDevice) [2024-05-17 08:53:46] info: z2m: small_room_weather_1 (0x00158d000a81f3e0): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-17 08:53:46] info: z2m: balcony_dimmer_1 (0xa4c138467f6be91f): TS0601_dimmer_1 - TuYa 1 gang smart dimmer (Router) [2024-05-17 08:53:46] info: z2m: small_room_smoke_1 (0x54ef44100062e4c9): JY-GZ-01AQ - Aqara Smart smoke detector (EndDevice) [2024-05-17 08:53:46] info: z2m: Zigbee: disabling joining new devices. [2024-05-17 08:53:46] info: z2m: Connecting to MQTT server at mqtt://core-mosquitto:1883 [2024-05-17 08:53:47] info: z2m: Connected to MQTT server [2024-05-17 08:53:47] info: z2m: Started frontend on port 8099 [2024-05-17 08:53:47] info: z2m: Zigbee2MQTT started! [2024-05-17 08:53:47] error: zh:ember: Delivery of BROADCAST failed for "65532" [apsFrame={"profileId":0,"clusterId":54,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":225} messageTag=1] [2024-05-17 08:53:47] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":224} messageTag=255] [2024-05-17 09:06:40] info: z2m: Removing device 'balcony_dimmer_1' (block: false, force: true) [2024-05-17 09:06:40] info: z2m: Successfully removed device 'balcony_dimmer_1' (block: false, force: true) [2024-05-17 09:06:46] info: z2m: Disconnecting from MQTT server [2024-05-17 09:06:46] info: z2m: Stopping zigbee-herdsman... [2024-05-17 09:06:46] info: zh:controller: Wrote coordinator backup to '/config/zigbee2mqtt/coordinator_backup.json' [2024-05-17 09:06:46] info: zh:ember:uart:ash: ASH COUNTERS since last clear: [2024-05-17 09:06:46] info: zh:ember:uart:ash: Total frames: RX=1038, TX=1174 [2024-05-17 09:06:46] info: zh:ember:uart:ash: Cancelled : RX=0, TX=0 [2024-05-17 09:06:46] info: zh:ember:uart:ash: DATA frames : RX=1037, TX=141 [2024-05-17 09:06:46] info: zh:ember:uart:ash: DATA bytes : RX=32281, TX=2699 [2024-05-17 09:06:46] info: zh:ember:uart:ash: Retry frames: RX=0, TX=0 [2024-05-17 09:06:46] info: zh:ember:uart:ash: ACK frames : RX=0, TX=1032 [2024-05-17 09:06:46] info: zh:ember:uart:ash: NAK frames : RX=0, TX=0 [2024-05-17 09:06:46] info: zh:ember:uart:ash: nRdy frames : RX=0, TX=0 [2024-05-17 09:06:46] info: zh:ember:uart:ash: CRC errors : RX=1 [2024-05-17 09:06:46] info: zh:ember:uart:ash: Comm errors : RX=0 [2024-05-17 09:06:46] info: zh:ember:uart:ash: Length < minimum: RX=0 [2024-05-17 09:06:46] info: zh:ember:uart:ash: Length > maximum: RX=0 [2024-05-17 09:06:46] info: zh:ember:uart:ash: Bad controls : RX=0 [2024-05-17 09:06:46] info: zh:ember:uart:ash: Bad lengths : RX=0 [2024-05-17 09:06:46] info: zh:ember:uart:ash: Bad ACK numbers : RX=0 [2024-05-17 09:06:46] info: zh:ember:uart:ash: Out of buffers : RX=0 [2024-05-17 09:06:46] info: zh:ember:uart:ash: Retry dupes : RX=0 [2024-05-17 09:06:46] info: zh:ember:uart:ash: Out of sequence : RX=0 [2024-05-17 09:06:46] info: zh:ember:uart:ash: ACK timeouts : RX=0 [2024-05-17 09:06:46] info: zh:ember:uart:ash: Port closed. Error? no [2024-05-17 09:06:46] info: zh:ember:uart:ash: ======== ASH stopped ======== [2024-05-17 09:06:46] info: zh:ember:ezsp: ======== EZSP stopped ======== [2024-05-17 09:06:46] info: zh:ember: ======== Ember Adapter Stopped ======== [2024-05-17 09:06:46] info: z2m: Stopped zigbee-herdsman [2024-05-17 09:06:46] info: z2m: Stopped Zigbee2MQTT [09:06:47] INFO: Preparing to start... [09:06:47] INFO: Socat not enabled [09:06:49] INFO: Starting Zigbee2MQTT... [2024-05-17 09:06:51] info: z2m: Logging to console, file (filename: log.log) [2024-05-17 09:06:51] info: z2m: Starting Zigbee2MQTT version 1.37.1 (commit #unknown) [2024-05-17 09:06:51] info: z2m: Starting zigbee-herdsman (0.46.6) [2024-05-17 09:06:51] info: zh:ember: ======== Ember Adapter Starting ======== [2024-05-17 09:06:51] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-05-17 09:06:51] info: zh:ember:uart:ash: ======== ASH NCP reset ======== [2024-05-17 09:06:51] info: zh:ember:uart:ash: Serial port opened [2024-05-17 09:06:51] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-05-17 09:06:52] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-05-17 09:06:52] info: zh:ember:uart:ash: ======== ASH started ======== [2024-05-17 09:06:52] info: zh:ember:ezsp: ======== EZSP started ======== [2024-05-17 09:06:53] info: zh:ember: [STACK STATUS] Network up. [2024-05-17 09:06:53] info: zh:ember: [INIT TC] NCP network matches config. [2024-05-17 09:06:53] info: zh:ember: [CONCENTRATOR] Started source route discovery. 1248ms until next broadcast. [2024-05-17 09:06:53] info: z2m: zigbee-herdsman started (resumed) [2024-05-17 09:06:53] info: z2m: Coordinator firmware version: '{"meta":{"build":0,"ezsp":13,"major":7,"minor":4,"patch":3,"revision":"7.4.3 [GA]","special":0,"type":170},"type":"EmberZNet"}' [2024-05-17 09:06:53] info: z2m: Currently 21 devices are joined: [2024-05-17 09:06:53] info: z2m: hot_water_valve (0x70b3d52b600242ac): ZN231392 - TuYa Smart water/gas valve (Router) [2024-05-17 09:06:53] info: z2m: cold_water_valve (0x70b3d52b600245e4): ZN231392 - TuYa Smart water/gas valve (Router) [2024-05-17 09:06:53] info: z2m: bathroom_water_leak_1 (0x00158d0008e0380b): SJCGQ11LM - Aqara Water leak sensor (EndDevice) [2024-05-17 09:06:53] info: z2m: bathroom_water_leak_2 (0x00158d0008dfb8d1): SJCGQ11LM - Aqara Water leak sensor (EndDevice) [2024-05-17 09:06:53] info: z2m: big_room_weather_1 (0x00158d0006fab9c2): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-17 09:06:53] info: z2m: bathroom_weather_1 (0x00158d000759b371): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-17 09:06:53] info: z2m: kitchen_weather_1 (0x00158d00073a14ff): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-17 09:06:53] info: z2m: big_room_motion_1 (0x54ef44100052bbc7): RTCGQ14LM - Aqara Motion sensor P1 (EndDevice) [2024-05-17 09:06:53] info: z2m: corridor_opening_1 (0x54ef44100044b12d): MCCGQ13LM - Aqara Door and window sensor P1 (EndDevice) [2024-05-17 09:06:53] info: z2m: balcony_weather_1 (0x00158d00073a1815): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-17 09:06:53] info: z2m: toilet_weather_1 (0x00158d000a81f3b4): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-17 09:06:53] info: z2m: kitchen_water_leak_1 (0x00158d0008dff1a0): SJCGQ11LM - Aqara Water leak sensor (EndDevice) [2024-05-17 09:06:53] info: z2m: kitchen_water_leak_2 (0x00158d0008e0ad11): SJCGQ11LM - Aqara Water leak sensor (EndDevice) [2024-05-17 09:06:53] info: z2m: corridor_motion_1 (0x54ef44100052cdbf): RTCGQ14LM - Aqara Motion sensor P1 (EndDevice) [2024-05-17 09:06:53] info: z2m: corridor_motion_2 (0x54ef44100052cd9b): RTCGQ14LM - Aqara Motion sensor P1 (EndDevice) [2024-05-17 09:06:53] info: z2m: kitchen_motion_1 (0x54ef44100052bc28): RTCGQ14LM - Aqara Motion sensor P1 (EndDevice) [2024-05-17 09:06:53] info: z2m: kitchen_smoke_1 (0x54ef441000711e13): JY-GZ-01AQ - Aqara Smart smoke detector (EndDevice) [2024-05-17 09:06:53] info: z2m: balcony_motion_1 (0x54ef44100052d0b3): RTCGQ14LM - Aqara Motion sensor P1 (EndDevice) [2024-05-17 09:06:53] info: z2m: big_room_smoke_1 (0x54ef44100062f13d): JY-GZ-01AQ - Aqara Smart smoke detector (EndDevice) [2024-05-17 09:06:53] info: z2m: small_room_weather_1 (0x00158d000a81f3e0): WSDCGQ11LM - Aqara Temperature and humidity sensor (EndDevice) [2024-05-17 09:06:53] info: z2m: small_room_smoke_1 (0x54ef44100062e4c9): JY-GZ-01AQ - Aqara Smart smoke detector (EndDevice) [2024-05-17 09:06:53] info: z2m: Zigbee: disabling joining new devices. [2024-05-17 09:06:53] info: z2m: Connecting to MQTT server at mqtt://core-mosquitto:1883 [2024-05-17 09:06:53] info: z2m: Connected to MQTT server [2024-05-17 09:06:53] info: z2m: Started frontend on port 8099 [2024-05-17 09:06:53] info: z2m: Zigbee2MQTT started! ```
Nerivec commented 4 months ago

@Ricc68 Do you have a log file I can take a look at?

@SubZero77 Interesting, could be the dimmer is a terrible router, Tuya is good at that. 😅 Or it could be linked to the Z2M restart itself (which restarts the adapter)... Use only these settings for your zbdongle-e:

serial:
  port: /dev/ttyACM0
  adapter: ember
  baudrate: 230400

(remove rtscts line, zbdongle-e doesn't have hardware flow control)

majorsl commented 4 months ago

I'm having many problems too. I updated to 1.37.1 and noted the upcoming change in the log. I went ahead and changed my config and restarted docker. I'm on an RPi 3b if that is relevant.

It mostly controls a dozen blinds. Here is a bit from the logs, but they all are the same:

2024-05-18 10:44:36Publish 'set' 'position' to 'Master Bedroom Blind 1' failed: 'Error: ZCL command 0x282c02bfffea0f99/1 closuresWindowCovering.goToLiftPercentage({"percentageliftvalue":43}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed ({"target":53567,"apsFrame":{"profileId":260,"clusterId":258,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":17},"zclSequence":8,"commandIdentifier":11} timed out after 10000ms)' Warning 2024-05-18 10:44:53NOT READY - Signaling NCP

My adapter is a Dongle-E. I noted here that upgrading 7.4.3.0 might help (I was on 7.4.1.0). It did not. I am using a USB extension cable which is always recommended, of course.

The previous driver has been stable and working with no errors in my logs except for a rare retry for maybe a year now? I went ahead and reverted and things are back to normal.

Nerivec commented 4 months ago

@majorsl Please create a new issue with a debug log attached as your issue appears unrelated to this one.

Ricc68 commented 4 months ago

@Nerivec good news I think: yesterday I have restarted z2m with log debug but in 24h I did not receive any broadcast error. I have checked all the broadcasts and they are all to destination 65533 and they are all type=BROADCAST and status=SUCCESS. I will keep the debug log and see if it will happen again in the next 24h, otherwise I will call it fixed and the occasional broadcast error just a glitch in my zigbee network.

IetIesAai commented 4 months ago

I also had this problem with my skyconnect on firmware 7.4.2 - and by pure coincidence I noticed the placement of the dongle had something to do with it. I used something like bluetack to hold the dongle and usb extension lead (on a usb 2 port) to the side of the wood cabinet. This has worked well with ezsp for a year or so. After upgrading to 7.4.2 and changing to ember, I immediately had the described issue with broadcasts. However, due to removing the dongle for the firmware upgrade, it wasn't as well connected to the wall as before, and it dropped down. Suddenly the zigbee network started performing without any problem with the ember driver. (though I also upgraded to the latest version of Z2m, so I thought this had solved it). I noticed the dongle had fallen down, and put it back in it's place, and the issue returned!

I now upgraded firmware to 7.4.3 and so far haven't been able to reproduce the issue anymore.... Very strange, but who knows this description helps in tracking it down....

remb0 commented 4 months ago

I have the same error.
skyconnect (all firmware versions tested) strange thing is that only my powered devices(routers) are staying offline

IetIesAai commented 4 months ago

I have the same error. skyconnect (all firmware versions tested) strange thing is that only my powered devices(routers) are staying offline

Just wondering if it only seems that way, because powered devices are typically pinged much more frequently, and thus show as "offline" much sooner than battery devices....

Ricc68 commented 4 months ago

Ok I confirm that in the last 48h I haven't had any broadcast error with fw 7.4.3. I'll disable debug now: to me is fixed.

itwtds commented 4 months ago

I have the same error. skyconnect (all firmware versions tested) strange thing is that only my powered devices(routers) are staying offline

Just wondering if it only seems that way, because powered devices are typically pinged much more frequently, and thus show as "offline" much sooner than battery devices....

This is what I see as well. I tried running it for an extended period, and they ultimately all go offline.

extreme4u commented 4 months ago

@IetIesAai

I also had this problem with my skyconnect on firmware 7.4.2 - and by pure coincidence I noticed the placement of the dongle had something to do with it. I used something like bluetack to hold the dongle and usb extension lead (on a usb 2 port) to the side of the wood cabinet. This has worked well with ezsp for a year or so. After upgrading to 7.4.2 and changing to ember, I immediately had the described issue with broadcasts. However, due to removing the dongle for the firmware upgrade, it wasn't as well connected to the wall as before, and it dropped down. Suddenly the zigbee network started performing without any problem with the ember driver. (though I also upgraded to the latest version of Z2m, so I thought this had solved it). I noticed the dongle had fallen down, and put it back in it's place, and the issue returned!

I now upgraded firmware to 7.4.3 and so far haven't been able to reproduce the issue anymore.... Very strange, but who knows this description helps in tracking it down....

My Skyconnect is currently running on version 7.4.2, and I was able to reproduce the behavior you described. My Skyconnect is also connected with a USB extension and was mounted on a wall surrounded by wood using double-sided tape. As a test, I placed the dongle on the floor. Suddenly, the lamps could be switched on and off without any problems. This behavior is highly interesting.

Unfortunately, I cannot find the firmware version 7.4.3. Where can I download this version?

IetIesAai commented 4 months ago

@IetIesAai

I also had this problem with my skyconnect on firmware 7.4.2 - and by pure coincidence I noticed the placement of the dongle had something to do with it. I used something like bluetack to hold the dongle and usb extension lead (on a usb 2 port) to the side of the wood cabinet. This has worked well with ezsp for a year or so. After upgrading to 7.4.2 and changing to ember, I immediately had the described issue with broadcasts. However, due to removing the dongle for the firmware upgrade, it wasn't as well connected to the wall as before, and it dropped down. Suddenly the zigbee network started performing without any problem with the ember driver. (though I also upgraded to the latest version of Z2m, so I thought this had solved it). I noticed the dongle had fallen down, and put it back in it's place, and the issue returned! I now upgraded firmware to 7.4.3 and so far haven't been able to reproduce the issue anymore.... Very strange, but who knows this description helps in tracking it down....

My Skyconnect is currently running on version 7.4.2, and I was able to reproduce the behavior you described. My Skyconnect is also connected with a USB extension and was mounted on a wall surrounded by wood using double-sided tape. As a test, I placed the dongle on the floor. Suddenly, the lamps could be switched on and off without any problems. This behavior is highly interesting.

Unfortunately, I cannot find the firmware version 7.4.3. Where can I download this version?

I got it from https://github.com/darkxst/silabs-firmware-builder/blob/4.4.3/firmware_builds/skyconnect/ncp-uart-hw-v7.4.3.0-skyconnect-115200.gbl

btw: that one also seems to work with rts/cts: true (hardware flow control) - the previous ones didn't for me.

supaeasy commented 4 months ago

For the Silicon Labs flasher you need the raw link: https://github.com/darkxst/silabs-firmware-builder/raw/4.4.3/firmware_builds/zbdonglee/ncp-uart-hw-v7.4.3.0-zbdonglee-115200.gbl

I just updated, will see if that works better.

I also found that at least one, maybe two IKEA Tradfri bulbs are having problems: they stop reacting and when I switch them off and on again they start minimally dimmed. After that they are starting to react normally again - for some time. Then the error happens again. Will see if the new fw helps.

remb0 commented 4 months ago

I have it working now. what I changed: swapped all usb ports and configure them again in proxmox. all got other names, and no duplicate mountings. I put rtscs: false instead of not having that line, and also added the baudrate, however I use the default.

rebooted the system and it's working now.

Nerivec commented 4 months ago

For anyone that can't seem to fix this, you can try clearing the NVM3 on your adapter. Make sure to follow the procedure properly to ensure you can restore your network config after (otherwise need to re-pair everything). https://github.com/darkxst/silabs-firmware-builder/issues/84#issuecomment-2094078288

If you don't care about restoring your network config, you can just flash the init file like a regular firmware, then flash the proper firmware for your adapter.

extreme4u commented 4 months ago

@IetIesAai

I also had this problem with my skyconnect on firmware 7.4.2 - and by pure coincidence I noticed the placement of the dongle had something to do with it. I used something like bluetack to hold the dongle and usb extension lead (on a usb 2 port) to the side of the wood cabinet. This has worked well with ezsp for a year or so. After upgrading to 7.4.2 and changing to ember, I immediately had the described issue with broadcasts. However, due to removing the dongle for the firmware upgrade, it wasn't as well connected to the wall as before, and it dropped down. Suddenly the zigbee network started performing without any problem with the ember driver. (though I also upgraded to the latest version of Z2m, so I thought this had solved it). I noticed the dongle had fallen down, and put it back in it's place, and the issue returned! I now upgraded firmware to 7.4.3 and so far haven't been able to reproduce the issue anymore.... Very strange, but who knows this description helps in tracking it down....

My Skyconnect is currently running on version 7.4.2, and I was able to reproduce the behavior you described. My Skyconnect is also connected with a USB extension and was mounted on a wall surrounded by wood using double-sided tape. As a test, I placed the dongle on the floor. Suddenly, the lamps could be switched on and off without any problems. This behavior is highly interesting. Unfortunately, I cannot find the firmware version 7.4.3. Where can I download this version?

I got it from https://github.com/darkxst/silabs-firmware-builder/blob/4.4.3/firmware_builds/skyconnect/ncp-uart-hw-v7.4.3.0-skyconnect-115200.gbl

btw: that one also seems to work with rts/cts: true (hardware flow control) - the previous ones didn't for me.


Thanks, I just flashed to 7.3.3. It is super important to use the USB cable extension to avoid USB interference. Otherwise, you get these broadcast errors. My setup is now working with this USB extension and Skyconnect on 7.3.3 and EmberZNet.

I am now getting these errors at startup:

[14:46:03] INFO: Preparing to start...
[14:46:04] INFO: Socat not enabled
[14:46:04] INFO: Starting Zigbee2MQTT...
[2024-05-20 14:46:07] error:  zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=RESET_WATCHDOG.
[2024-05-20 14:46:07] error:  zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR
[2024-05-20 14:46:07] error:  zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.

Since 14:46, no more errors have occurred. Just a ton of debug info. @Nerivec, if you want, I can send you the debug log. However, I would like to send it directly and not publicly. Of course, only if it will help to fix problems.

Nerivec commented 4 months ago

@extreme4u Those errors at startup (RESET_WATCHDOG) are due to a hardware flow control bug. It's being tracked, silabs is aware, but it's been around for a long time... both Z2M and ZHA implement a retry mechanism to work around it. It should not prevent proper start, let me know if it ever does. If you want to get rid of these errors entirely, darkxst has a branch of firmware with hardware flow control disabled; these should result in "cleaner" starts. https://github.com/darkxst/silabs-firmware-builder/tree/ember-nohw/firmware_builds (make sure to use these with rtscts: false)

PS: If you ever want to share logs directly, you can find me on zigbee2mqtt discord, then send me a DM.

LDprg commented 4 months ago

For me it was fixed by following steps (note that it involves reconnecting all devices):

1) shutdown zigee2mqtt and the mqtt server 2) flash nvm3 and afterwards flash 7.4.3 firmware onto the dongle e 3) delete all mqtt data (especially the database) except config 4) delete all zigbee2mqtt data except config (note that all config including homeassitant entity ids are saved in the config no information lost, they will be set after reconnecting the device) 5) change the zigee2mqtt config file to use the zigbee channel 25 (probably the best channels) 6) clean your config file (take a backup first), delete unnecessary config which just sets the default, delete config which doesn't seem necessary and add adapter: ember to the dongle config 7) change your all network ids using GENERATE in the z2m config 8) verify that your wifi isn't on the wifi channel 11 (because of interference with zigbee) 9) restart zigee2mqtt and mqtt 10) reconnect your devices 11) ignore errors thrown and do not connect multiple devices at the same time or too quickly after each other

Quite some work, but it works great now (even better than donglep). I still get some error but no notable effect on the zigbee network.

Note that this is only a quick summary of what I did and I am just a casual z2m user. So be careful and take a backup first.

IetIesAai commented 4 months ago

@IetIesAai

I also had this problem with my skyconnect on firmware 7.4.2 - and by pure coincidence I noticed the placement of the dongle had something to do with it. I used something like bluetack to hold the dongle and usb extension lead (on a usb 2 port) to the side of the wood cabinet. This has worked well with ezsp for a year or so. After upgrading to 7.4.2 and changing to ember, I immediately had the described issue with broadcasts. However, due to removing the dongle for the firmware upgrade, it wasn't as well connected to the wall as before, and it dropped down. Suddenly the zigbee network started performing without any problem with the ember driver. (though I also upgraded to the latest version of Z2m, so I thought this had solved it). I noticed the dongle had fallen down, and put it back in it's place, and the issue returned! I now upgraded firmware to 7.4.3 and so far haven't been able to reproduce the issue anymore.... Very strange, but who knows this description helps in tracking it down....

My Skyconnect is currently running on version 7.4.2, and I was able to reproduce the behavior you described. My Skyconnect is also connected with a USB extension and was mounted on a wall surrounded by wood using double-sided tape. As a test, I placed the dongle on the floor. Suddenly, the lamps could be switched on and off without any problems. This behavior is highly interesting.

Unfortunately, I cannot find the firmware version 7.4.3. Where can I download this version?

Meanwhile, having had some more time in use, I must say the Ember driver + skyconnect for some reason seems to be much more prone to interference - I never noticed this with the same dongle in more or less the same location before. Having been swapping out some components such as a switch in the cupboard where the server and thus the dongles (on a usb extension lead on usb 2) are kept, I noticed for my environment the placement of the dongle is much more finicky now then I ever remember it being before. I changed the location and the usb extension lead, and for now it seems stable again, but I don't remember it being that picky before....

kwiatkowskimarcinb commented 4 months ago

I've had the same issue, and for me adding:

advanced:
    network_key: GENERATE

in data/configuration.yaml solved the issue: I no longer receive "Delivery of BROADCAST failed ..." errors.

WARNING: This will require re-pairing all devices.

huotarih commented 4 months ago

I've had the same issue, and for me adding:

advanced:
    network_key: GENERATE

in data/configuration.yaml solved the issue: I no longer receive "Delivery of BROADCAST failed ..." errors.

This also deletes all devices. Atleast it did for me. And still have the error.

kwiatkowskimarcinb commented 4 months ago

I've had the same issue, and for me adding:

advanced:
    network_key: GENERATE

in data/configuration.yaml solved the issue: I no longer receive "Delivery of BROADCAST failed ..." errors.

This also deletes all devices. Atleast it did for me. And still have the error.

That's right - generating a new key forces you to re-pair your devices. An it makes sense only if you don't have it generated before.

I use the latest firmware for the Zigbee Dongle E device: ncp-uart-hw-v7.4.3.0-zbdonglee-115200.gbl

lennon101 commented 4 months ago

Hi team! Just adding my own 2 cents here for anyone wondering what they can do in the meantime until this is fixed: I have rolled back my zigbee2mqtt server version while keeping the updated firmware on the Sonoff dongle.

Steps were:

Ricc68 commented 4 months ago

I have to report that checking the logs I still have the broadcast errors. Fw 7.4.3 does not fix the issue:

[2024-06-03 22:22:56] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-03 22:22:56] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-06-03 22:22:56] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-06-03 22:22:56] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-06-03 22:22:56] debug: zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=109 Len=22] [2024-06-03 22:22:56] debug: zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=BROADCAST], [indexOrDestination=65533], [apsFrame={"profileId":0,"clusterId":6,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":5}], [messageTag=255], [status=DELIVERY_FAILED], [messageContents=] [2024-06-03 22:22:56] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":6,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":5} messageTag=255]

huotarih commented 4 months ago

Hi team! Just adding my own 2 cents here for anyone wondering what they can do in the meantime until this is fixed: I have rolled back my zigbee2mqtt server version while keeping the updated firmware on the Sonoff dongle.

Steps were:

  • rolled back to zigbee2mqtt server version1.36.1 and changed the settings in the configuation.yaml

    serial: port: /dev/ttyACM0 adapter: ezsp baudrate: 115200 rtscts: false

  • Network returned to a completely working state (all devices have returned to network and all routers have also returned)

    • no errors in the log either
  • Final state of working system is:

    • Zigbee2mqtt Server Version: 1.36.1 running docker container
    • Zigbee2mqtt coordinator version: 7.4.3
    • configuration.yaml settings specific to fixing this issue:

      serial: adapter: ezsp

How did you downgrade? I can't figure out how to downgrade without losing the data because I installed z2m through home assistant add-ons.

j-paulus commented 4 months ago

As I had this issue along with others making the system quite unreliable, I downgraded to 1.36.1 which solved the problems. This was possible using by selecting the correct HA backup (usually created at the start of the update) and selecting only z2m to be restored. If you don't have a backup, then this may be more work.

lennon101 commented 4 months ago

How did you downgrade? I can't figure out how to downgrade without losing the data because I installed z2m through home assistant add-ons.

@huotarih yeah sorry mate, I would have no idea on that one. I use Z2M in a docker container so it's easy for me. Surely it can be done though?

supaeasy commented 4 months ago

Can confirm the main problem is with ember driver. Ever since I changed back from ember to ezsp (Latest Z2M, Dongle E with 7.4.3) the startup error messages (but no others) are back but all actual problems are completely gone. Will stay there for a while.

huotarih commented 4 months ago

Figured out how to downgrade. Depends of course if you still have the backup. Settings -> System -> Backups -> Search for zigbee -> Choose 1.36.1 -> Choose add-ons -> Restore

Screenshot 2024-06-06 at 12 02 19 Screenshot 2024-06-06 at 12 02 51
drueppela commented 4 months ago

What happened?

Deprecated driver 'ezsp' currently in use, 'ember' will become the officially supported EmberZNet driver in next release. If using Zigbee2MQTT see https://github.com/Koenkk/zigbee2mqtt/discussions/21462

I tried to run SMLIGHT SLZB-06M & Zigbee2MQTT with configuration "ember" although SMLIGHT obviously does not yet recommend this. See "SMLIGHT SLZB-06M control panel Zigbee2MQTT config generator"

NOT WORKING Zigbee2MQTT configuration.yaml

serial:
  port: tcp://slzb-06m.local:6638
  baudrate: 115200
  adapter: ember
  rtscts: false
  disable_led: false
advanced:
  transmit_power: 20
  homeassistant_legacy_entity_attributes: false
  legacy_api: false
  legacy_availability_payload: false
  log_level: error
frontend:
  port: 8099
device_options:
  legacy: false

What did you expect to happen?

Zigbee2MQTT with adapter: ember is running without errors

SMLIGHT SLZB-06M control panel Zigbee2MQTT config generator

# Pay attention, if you use the Z2M addon for HA, it is better to edit the yaml configuration file directly
serial:
# Location of SLZB-06M
  port: tcp://slzb-06m.local:6638
  baudrate: 115200
  adapter: ezsp
# Disable green led?
  disable_led: false
# Set output power to max 20
advanced:
  transmit_power: 20

How to reproduce it (minimal and precise)

Setting

serial:
  adapter: ember

in the following environment

Zigbee2MQTT version

Current version: 1.38.0-1

Adapter

SMLIGHT SLZB-06M

Adapter firmware version

[7.4.2.0 build 0](firmware: v2.3.6)

Radio FW version

20240510

Coordinator mode

LAN

Setup

GEEKOM Mini IT13 Mini PC 13th Gen Intel® Core i9-13900H 32GB RAM+2TB SSD Proxmox Virtual Environment 8.2.2 Home Assistant Core 2024.6.0 Home Assistant Supervisor 2024.06.0 Home Assistant Operating System 12.3 Home Assistant Frontend 20240605.0

SLZB-06M System Log ``` [00:00:00] setup | Starting firmware: v2.3.6 [00:00:01] ConfigHelper | LittleFS mounted [00:00:01] ConfigHelper | load config [00:00:01] ConfigHelper | config open: Ok [00:00:01] setup | Config loaded [00:00:01] setup | Reboot reason: 1 [00:00:01] setup | Coordinator mode: LAN [00:00:01] setup | Radio FW version: 20240510 [00:00:01] setup | Device type: SLZB-06M [00:00:01] setup | Radio mode: ZB COORD [00:00:01] Network | init [00:00:01] L_Y,L_B | status: 1 [00:00:02] Network | EVENT_ETH_START [00:00:02] Network | EVENT_ETH_CONNECTED [00:00:02] Network | ETH init: OK [00:00:02] Network | ETH static IP config: OK [00:00:02] Network | [MDNS] Started [00:00:02] setup | Filesystem size: 3456 [00:00:02] Network | EVENT_ETH_GOT_IP [00:00:02] Network | ETH MAC: C8:2E:18:52:5A:0F IPv4: 10.0.0.51 GW: 10.0.0.1 Speed: 100Mbps DNS1: 10.0.0.1 DNS2: 10.0.0.1 [00:00:02] Network | fireNetworkUp [00:00:02] taskZB | Start task [00:00:02] taskZB | Starting server on port: 6638 [00:00:02] Web | Webserver started [00:00:02] time | time sync start [00:00:02] internet | connected [00:00:02] setup | Filesystem used: 248 [00:00:02] setup | done [00:00:03] Network | [POST] result: 200 [00:00:03] Network | [POST] response: New record [on] created successfullyNew record [lo] created successfully [00:00:03] stats | Statistics sent [00:00:03] stats | Heap: 2380 [21:10:28] time | timezone: IST-1GMT0,M10.5.0,M3.5.0/1 [21:10:28] time | Wednesday, June 05 2024 21:10:28 [21:10:28] taskTimeSync | Heap: 1500 [21:10:28] time | stop task [21:10:31] [ZBCHK] | Wrong answer [21:10:31] [ZBVER] | Unknown [21:10:32] [ZBCHK] | done [21:16:38] taskZB | New client: 10.0.0.50 id: 4 [00:15:42] ConfigHelper | write config [00:15:42] ConfigHelper | config saved [00:19:34] ConfigHelper | write config [00:19:34] ConfigHelper | config saved [16:09:06] ConfigHelper | write config [16:09:06] ConfigHelper | config saved [16:10:33] ConfigHelper | write config [16:10:33] ConfigHelper | config saved [16:45:13] taskZB | Client disconnected, id: 4 [16:45:17] taskZB | New client: 10.0.0.50 id: 0 [16:45:29] taskZB | Client disconnected, id: 0 [16:45:31] taskZB | New client: 10.0.0.50 id: 0 [16:48:01] taskZB | Client disconnected, id: 0 [16:48:02] taskZB | New client: 10.0.0.50 id: 0 [16:48:14] taskZB | Client disconnected, id: 0 [16:48:15] taskZB | New client: 10.0.0.50 id: 0 [16:50:33] taskZB | Client disconnected, id: 0 [16:50:35] taskZB | New client: 10.0.0.50 id: 0 [16:50:46] taskZB | Client disconnected, id: 0 [16:50:48] taskZB | New client: 10.0.0.50 id: 0 ```
Zigbee2MQTT Log ``` [2024-06-06 17:09:59] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":196} messageTag=255] [2024-06-06 17:10:00] error: zh:ember: [ZDO] Failed permit joining request with status=NETWORK_BUSY. [2024-06-06 17:10:00] error: zh:ember: [ZDO] Failed permit joining request with status=NETWORK_BUSY. [2024-06-06 17:10:01] error: zh:ember: [ZDO] Failed permit joining request with status=NETWORK_BUSY. [2024-06-06 17:10:01] error: zh:ember: [ZDO] Failed permit joining request with status=NETWORK_BUSY. [2024-06-06 17:10:03] error: zh:ember: Delivery of BROADCAST failed for "65532" [apsFrame={"profileId":0,"clusterId":54,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":54} messageTag=35] [2024-06-06 17:10:03] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":55} messageTag=120] [2024-06-06 17:10:08] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":199} messageTag=255] [2024-06-06 17:10:13] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":7} messageTag=255] [2024-06-06 17:10:14] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":201} messageTag=255] [2024-06-06 17:10:20] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":9} messageTag=255] [2024-06-06 17:10:23] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":10} messageTag=255] [2024-06-06 17:10:23] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":204} messageTag=255] [2024-06-06 17:10:29] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":12} messageTag=255] [2024-06-06 17:10:35] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":14} messageTag=255] [2024-06-06 17:10:38] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":15} messageTag=255] [2024-06-06 17:10:38] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":209} messageTag=255] [2024-06-06 17:10:44] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":17} messageTag=255] [2024-06-06 17:10:50] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":19} messageTag=255] [2024-06-06 17:10:53] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":214} messageTag=255] [2024-06-06 17:10:59] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":216} messageTag=255] [2024-06-06 17:11:03] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":23} messageTag=255] [2024-06-06 17:11:08] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":219} messageTag=255] [2024-06-06 17:11:14] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":221} messageTag=255] [2024-06-06 17:11:17] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":222} messageTag=255] [2024-06-06 17:11:18] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":28} messageTag=255] [2024-06-06 17:11:23] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":224} messageTag=255] [2024-06-06 17:11:29] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":226} messageTag=255] [2024-06-06 17:11:32] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":227} messageTag=255] [2024-06-06 17:11:33] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":33} messageTag=255] [2024-06-06 17:11:38] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":229} messageTag=255] [2024-06-06 17:11:42] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":36} messageTag=255] [2024-06-06 17:11:47] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":232} messageTag=255] [2024-06-06 17:11:49] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":38} messageTag=255] [2024-06-06 17:11:53] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":234} messageTag=255] [2024-06-06 17:11:58] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":41} messageTag=255] [2024-06-06 17:12:02] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":237} messageTag=255] [2024-06-06 17:12:07] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":44} messageTag=255] [2024-06-06 17:12:08] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":239} messageTag=255] [2024-06-06 17:12:13] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":46} messageTag=255] [2024-06-06 17:12:17] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":242} messageTag=255] [2024-06-06 17:12:22] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":49} messageTag=255] [2024-06-06 17:12:23] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":244} messageTag=255] [2024-06-06 17:12:29] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":51} messageTag=255] [2024-06-06 17:12:32] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":247} messageTag=255] [2024-06-06 17:12:38] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":54} messageTag=255] [2024-06-06 17:12:38] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":249} messageTag=255] [2024-06-06 17:12:44] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":56} messageTag=255] [2024-06-06 17:12:44] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":251} messageTag=255] [2024-06-06 17:12:47] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":57} messageTag=255] [2024-06-06 17:12:47] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":252} messageTag=255] [2024-06-06 17:12:53] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":59} messageTag=255] [2024-06-06 17:12:53] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":254} messageTag=255] [2024-06-06 17:12:59] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":61} messageTag=255] [2024-06-06 17:13:02] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":62} messageTag=255] [2024-06-06 17:13:02] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":1} messageTag=255] [2024-06-06 17:13:08] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":3} messageTag=255] [2024-06-06 17:13:08] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":64} messageTag=255] [2024-06-06 17:13:17] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":6} messageTag=255] [2024-06-06 17:13:18] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":67} messageTag=255] [2024-06-06 17:13:19] error: zh:ember: [ZDO] Failed permit joining request with status=NETWORK_BUSY. [2024-06-06 17:13:20] error: zh:ember: [ZDO] Failed permit joining request with status=NETWORK_BUSY. [2024-06-06 17:13:20] error: zh:ember: [ZDO] Failed permit joining request with status=NETWORK_BUSY. [2024-06-06 17:13:22] error: zh:ember: Delivery of BROADCAST failed for "65532" [apsFrame={"profileId":0,"clusterId":54,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":59} messageTag=39] [2024-06-06 17:13:22] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":60} messageTag=121] [2024-06-06 17:13:23] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":8} messageTag=255] [2024-06-06 17:13:27] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":70} messageTag=255] [2024-06-06 17:13:32] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":11} messageTag=255] [2024-06-06 17:13:33] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":72} messageTag=255] [2024-06-06 17:13:38] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":13} messageTag=255] [2024-06-06 17:13:42] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":75} messageTag=255] [2024-06-06 17:13:47] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":16} messageTag=255] [2024-06-06 17:13:48] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":77} messageTag=255] [2024-06-06 17:13:51] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":78} messageTag=255] [2024-06-06 17:13:56] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":19} messageTag=255] [2024-06-06 17:13:57] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":80} messageTag=255] [2024-06-06 17:14:02] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":21} messageTag=255] [2024-06-06 17:14:04] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":82} messageTag=255] [2024-06-06 17:14:07] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":83} messageTag=255] [2024-06-06 17:14:11] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":24} messageTag=255] [2024-06-06 17:14:13] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":85} messageTag=255] [2024-06-06 17:14:17] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":26} messageTag=255] [2024-06-06 17:14:22] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":88} messageTag=255] [2024-06-06 17:14:26] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":29} messageTag=255] [2024-06-06 17:14:28] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":90} messageTag=255] [2024-06-06 17:14:31] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":91} messageTag=255] [2024-06-06 17:14:32] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":31} messageTag=255] [2024-06-06 17:14:37] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":93} messageTag=255] [2024-06-06 17:14:41] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":34} messageTag=255] [2024-06-06 17:14:47] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":96} messageTag=255] [2024-06-06 17:14:53] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":98} messageTag=255] [2024-06-06 17:14:56] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":39} messageTag=255] [2024-06-06 17:15:02] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":101} messageTag=255] [2024-06-06 17:15:08] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":103} messageTag=255] [2024-06-06 17:15:11] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":104} messageTag=255] [2024-06-06 17:15:17] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":106} messageTag=255] [2024-06-06 17:15:23] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":48} messageTag=255] [2024-06-06 17:15:26] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":49} messageTag=255] [2024-06-06 17:15:36] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":112} messageTag=255] [2024-06-06 17:15:41] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":54} messageTag=255] [2024-06-06 17:15:42] error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":114} messageTag=255] ```

INTERMEDIATE SOLUTION

serial:
  adapter: ember ==> adapter: ezsp

NO Zigbee2MQTT downgrade

OPEN BUG (not sure about that) - Will contact SMLIGHT

Errors during Zigbee2MQTT start-up (WATCHDOG ENABLED!) ``` [17:50:34] INFO: Preparing to start... [17:50:34] INFO: Socat not enabled [17:50:34] INFO: Starting Zigbee2MQTT... [2024-06-06 17:50:42] error: zh:ezsp:uart: --> Error: Error: {"sequence":1} after 4000ms [2024-06-06 17:50:42] error: zh:ezsp:uart: -!- break waiting (1) [2024-06-06 17:50:42] error: zh:ezsp:uart: Can't send DATA frame (0,2,0): 00000004 [2024-06-06 17:50:47] error: zh:ezsp:uart: --> Error: Error: {"sequence":1} after 4000ms [2024-06-06 17:50:47] error: zh:ezsp:uart: -!- break rewaiting (1) [2024-06-06 17:50:47] error: zh:ezsp:uart: Can't resend DATA frame (0,2,1): 00000004 [2024-06-06 17:50:47] error: z2m: Error while starting zigbee-herdsman [2024-06-06 17:50:47] error: z2m: Failed to start zigbee [2024-06-06 17:50:47] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions [2024-06-06 17:50:47] error: z2m: Exiting... [2024-06-06 17:50:47] error: z2m: Error: Failure send version:{"type":"Buffer","data":[0,0,0,4]} at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:686:23 at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20) at Ezsp.version (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:466:24) at Driver.startup (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:173:9) at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:127:29) at Zigbee.start (/app/lib/zigbee.ts:62:27) at Controller.start (/app/lib/controller.ts:109:27) at start (/app/index.js:107:5) [17:50:47] INFO: Preparing to start... [17:50:47] INFO: Socat not enabled [17:50:47] INFO: Starting Zigbee2MQTT... ```
M3te0r commented 3 months ago

Hi I had exactly the same errors at @drueppela above, SMLIGHT SLZB-06M recently bought and with ember driver from the start, running well the first weeks, then 2 days ago it started mess ing up completely, I even tried to reset my network new channel and keys, repairring devices, but same error and lot of devices not responding Finally swithced to ezsp, seems to have fixed it for now

[2024-06-13 01:05:52] error:    zh:ember: ~x~> [ZCL to=32377] Failed to send request with status=MAX_MESSAGE_LIMIT_REACHED.
[2024-06-13 01:05:52] info:     zh:ember:queue: Request dispatching stopped; queue=18 priorityQueue=0
[2024-06-13 01:05:52] info:     z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Thermostat', payload '{"child_lock":null,"current_heating_setpoint":18,"deadzone_temperature":null,"heat":"OFF","linkquality":216,"local_temperature":23,"local_temperature_calibration":null,"max_temperature_limit":null,"min_temperature_limit":null,"preset":"hold","preset_mode":"hold","program":null,"running_state":"idle","sensor":null,"system_mode":"heat"}'
[2024-06-13 01:05:52] error:    zh:ember: Delivery of BROADCAST failed for "65535" [apsFrame={"profileId":260,"clusterId":10,"sourceEndpoint":1,"destinationEndpoint":1,"options":0,"groupId":0,"sequence":19} messageTag=255]
[2024-06-13 01:05:52] info:     zh:ember:queue: Request dispatching started.
[2024-06-13 01:05:52] error:    zh:ember: ~x~> [ZCL to=4372] Failed to send request with status=MAX_MESSAGE_LIMIT_REACHED.
[2024-06-13 01:05:52] info:     zh:ember:queue: Request dispatching stopped; queue=8 priorityQueue=0
[2024-06-13 01:05:52] info:     z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Thermostat', payload '{"child_lock":null,"current_heating_setpoint":18,"deadzone_temperature":null,"heat":"OFF","linkquality":216,"local_temperature":23,"local_temperature_calibration":null,"max_temperature_limit":null,"min_temperature_limit":null,"preset":"hold","preset_mode":"hold","program":null,"running_state":"idle","sensor":null,"system_mode":"heat"}'
[2024-06-13 01:05:53] info:     z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Thermostat', payload '{"child_lock":null,"current_heating_setpoint":18,"deadzone_temperature":null,"heat":"OFF","linkquality":216,"local_temperature":23,"local_temperature_calibration":null,"max_temperature_limit":null,"min_temperature_limit":null,"preset":"hold","preset_mode":"hold","program":null,"running_state":"idle","sensor":null,"system_mode":"heat"}'
[2024-06-13 01:05:53] info:     zh:ember:queue: Request dispatching started.
[2024-06-13 01:05:53] error:    zh:ember: ~x~> [ZCL to=4372] Failed to send request with status=MAX_MESSAGE_LIMIT_REACHED.
Nerivec commented 3 months ago

Since ezsp driver doesn't implement support for "delivery" at all (failures are just silently ignored), I added some logging in ezsp (currently in dev, will be in July release) to at least help identify the two issues that are getting mixed here:

  1. The original issue of this thread: all broadcasts start failing right after z2m start, network is not usable (or barely).
  2. Typical interferences: some broadcasts fail, network remains operational.

For anyone trying to help figure this out, when checking with ezsp, see in debug logs if you also find lines starting with: Delivery failed for. If you do, chances are, you are seeing the second one (since the original issue in this thread doesn't seem to affect ezsp for some reason).


@M3te0r You are getting MAX_MESSAGE_LIMIT_REACHED which is another problem altogether. Something appears to be heavily spamming your network (have to have over 32 in-flight messages to even see this error!), the adapter can't keep up.

drueppela commented 3 months ago

@Nerivec :

Since ezsp driver doesn't implement support for "delivery" at all (failures are just silently ignored), I added some logging in ezsp (currently in dev, will be in July release) to at least help identify the two issues that are getting mixed here:

  1. The original issue of this thread: all broadcasts start failing right after z2m start, network is not usable (or barely).
  2. Typical interferences: some broadcasts fail, network remains operational.

For anyone trying to help figure this out, when checking with ezsp, see in debug logs if you also find lines starting with: Delivery failed for. If you do, chances are, you are seeing the second one (since the original issue in this thread doesn't seem to affect ezsp for some reason).

@M3te0r You are getting MAX_MESSAGE_LIMIT_REACHED which is another problem altogether. Something appears to be heavily spamming your network (have to have over 32 in-flight messages to even see this error!), the adapter can't keep up.

First of all: Thanks.

a) Apologies if I caused trouble. Is there an Issue for 2?

b) My infrastructure is extremly critical for 5 persons and less critical for three cats. :-) Should @M3te0r and myself and all other with SMLIGHT SLZB-06M stop updating Zigbee2MQTT? As far as I can see ezsp will be deprecated but SMLIGHT SLZB-06M is not running with ember.

c) In the meantime i added two SMLIGHT SLZB-06M as router. Compared to SkyConnect & ZHA and SkyConnect & Zigbee2MQTT the setup "1x SMLIGHT SLZB-06M as coordinator & Zigbee2MQTT + 2x SMLIGHT SLZB-06M as router & Zigbee2MQTT" JUST WORKS and compared to SkyConnect & ZHA the combination SMLIGHT SLZB-06M & Zigbee2MQTT offers by far (BY FAR!!!!) many more funktions and much transperancy. The WebGUI of SMLIGHT SLZB-06M is absolutely great. The WebGui of Zigbee2MQTT is absolutely great. My appraoch to bet on SkyConnect & ZHA was a hell of a mistake.

d) I just sponsored @Koenkk : The ONLY reason for me to mention this is that I hope all of you Zigbee2MQTT Buddies think about supporting @Koenkk .

Go for https://github.com/sponsors/Koenkk

image

Nerivec commented 3 months ago

@drueppela

a) 2. is interferences, so the fix is usually on a case by case basis (could be the adapter's port, power, cable, could be some other network nearby, the usual suspects) But from what you mentioned before, you seem to be affected by 1., unless I misunderstood.

b) ezsp will no longer receive updates, it will stay as-is in future versions (except if critical bugs found or to maintain compatibility with the rest of Z2M). The SLZB-06M works with ember (had several testers on it during ember dev, and some users still reporting regularly). Although it had a few specific issues recently (firmware-related), but SMLight and darkxst have been working on solving them. This constant broadcast failing problem is affecting random (or at least reason unidentified) users, with various adapters. darkxst and I have been unable to reproduce it in this manner. I piled on "everything you shouldn't do" to get a maximum of interferences, and it still won't result in this constant broadcast failure... I also spent some time testing various changes with one affected user to make ember's code behave more like ezsp's, in the relevant areas, but that didn't make any difference whatsoever. darkxst ran some tests on low-end machines, again, no joy, and also confirmed near-identical power draws for both drivers, excluding that as a possible source of troubles. Logs from affected users have not proven helpful. And users who have solved it used different procedures that lack a common element... In short, it's a really annoying bug, that's still playing hide-and-seek. 😓

alainsch commented 3 months ago

My experience in this in the last 3 weeks.

I am running an HA setup with 2 instances of Z2M, each with its own SLZB-06M coordinator. The firmware is SMLight's 2.3.6 and darkxst's ncp-uart-hw-v7.4.3.0-slzb-06m-115200.

In Z2M, I used the ember driver. One coordinator has 48 devices, the other (only) 2

I tested these on 3 different environments:

1) Synology DS-1019+ with 32GB of RAM, in a VM with 3 CPUs and 8GB of RAM

2) HardKernel ODroid M1 with 8 GB RAM and M2 SSD

3) Intel NUC I3 with 16 GB RAM and SATA SSD

On the Synology and the ODroid, I noticed that while the initial startup of both Z2M succeeded after a full system reboot, a reboot of the add-on thereafter almost always failed. Once it failed, I couldn't get it right again, even after a system reboot.

It started with CRC errors, timeouts and finally the message that the driver had not started. I thought I had a screenshot of this somewhere, but can't find it at the moment....

The only solution was a reboot of the coordinator in question.

I have since switched to the Intel NUC I3 for a week and have not had this happen once. I have just rebooted Z2M several times and it always works.

Of course, it could all be a coincidence, but in the first 2 environments it almost always failed and on the NUC I don't (currently) manage to simulate...

alainsch commented 3 months ago

... and just after I posted my previous message, I do manage to simulate it on the NUC I3.

A full system reboot of the I3, requiring everything to restart completely caused both Z2Ms to fail.

Z2M instance 1 initial setup

13:28:04] INFO: Starting Zigbee2MQTT...
[2024-06-16 13:28:06] info:     z2m: Logging to console, file (filename: log.log)
[2024-06-16 13:28:06] info:     z2m: Starting Zigbee2MQTT version 1.38.0 (commit #unknown)
[2024-06-16 13:28:06] info:     z2m: Starting zigbee-herdsman (0.49.2)
[2024-06-16 13:28:06] info:     zh:ember: Using default stack config.
[2024-06-16 13:28:06] info:     zh:ember: ======== Ember Adapter Starting ========
[2024-06-16 13:28:06] info:     zh:ember:ezsp: ======== EZSP starting ========
[2024-06-16 13:28:06] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-06-16 13:28:06] info:     zh:ember:uart:ash: Socket ready
[2024-06-16 13:28:06] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-06-16 13:28:06] error:    zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-06-16 13:28:06] error:    zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR
[2024-06-16 13:28:06] error:    zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-06-16 13:28:06] error:    zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-06-16 13:28:06] error:    zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-06-16 13:28:06] error:    zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-06-16 13:28:06] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-06-16 13:28:06] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-06-16 13:28:07] info:     zh:ember:uart:ash: ======== ASH connected ========
[2024-06-16 13:28:07] info:     zh:ember:uart:ash: ======== ASH started ========
[2024-06-16 13:28:07] info:     zh:ember:ezsp: ======== EZSP started ========
[2024-06-16 13:28:09] warning:  zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e]
[2024-06-16 13:28:09] error:    zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE.
[2024-06-16 13:28:09] error:    zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR
[2024-06-16 13:28:09] error:    zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR.
[2024-06-16 13:28:09] error:    zh:ember: !!! NCP FATAL ERROR reason=HOST_FATAL_ERROR. ATTEMPTING RESET... !!!
[2024-06-16 13:28:09] info:     zh:ember:queue: Request dispatching stopped; queue=0 priorityQueue=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash: ASH COUNTERS since last clear:
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Total frames: RX=2, TX=3
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Cancelled   : RX=1, TX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   DATA frames : RX=0, TX=1
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   DATA bytes  : RX=0, TX=4
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Retry frames: RX=0, TX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   ACK frames  : RX=0, TX=1
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   NAK frames  : RX=0, TX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   nRdy frames : RX=0, TX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   CRC errors      : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Comm errors     : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Length < minimum: RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Length > maximum: RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Bad controls    : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Bad lengths     : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Bad ACK numbers : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Out of buffers  : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Retry dupes     : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Out of sequence : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   ACK timeouts    : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash: ======== ASH stopped ========
[2024-06-16 13:28:09] info:     zh:ember:ezsp: ======== EZSP stopped ========
[2024-06-16 13:28:09] info:     zh:ember: ======== Ember Adapter Stopped ========
[2024-06-16 13:28:09] info:     zh:ember: ======== Ember Adapter Starting ========
[2024-06-16 13:28:09] info:     zh:ember:ezsp: ======== EZSP starting ========
[2024-06-16 13:28:09] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-06-16 13:28:09] info:     zh:ember:uart:ash: Socket ready
[2024-06-16 13:28:09] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-06-16 13:28:10] info:     zh:ember:uart:ash: ======== ASH connected ========
[2024-06-16 13:28:10] info:     zh:ember:uart:ash: ======== ASH started ========
[2024-06-16 13:28:10] info:     zh:ember:ezsp: ======== EZSP started ========
[2024-06-16 13:28:11] info:     zh:ember: [STACK STATUS] Network up.
[2024-06-16 13:28:11] info:     zh:ember: [INIT TC] NCP network matches config.
[2024-06-16 13:28:11] info:     zh:ember: [CONCENTRATOR] Started source route discovery. 1247ms until next broadcast.
[2024-06-16 13:28:11] info:     zh:ember:queue: Request dispatching started.

Z2M instance 2 initial setup

[13:28:04] INFO: Starting Zigbee2MQTT...
[2024-06-16 13:28:06] info:     z2m: Logging to console, file (filename: log.log)
[2024-06-16 13:28:06] info:     z2m: Starting Zigbee2MQTT version 1.38.0 (commit #unknown)
[2024-06-16 13:28:06] info:     z2m: Starting zigbee-herdsman (0.49.2)
[2024-06-16 13:28:06] info:     zh:ember: Using default stack config.
[2024-06-16 13:28:06] info:     zh:ember: ======== Ember Adapter Starting ========
[2024-06-16 13:28:06] info:     zh:ember:ezsp: ======== EZSP starting ========
[2024-06-16 13:28:06] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-06-16 13:28:06] info:     zh:ember:uart:ash: Socket ready
[2024-06-16 13:28:06] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-06-16 13:28:06] error:    zh:ember:uart:ash: Received frame with CRC error
[2024-06-16 13:28:06] error:    zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-06-16 13:28:06] error:    zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR
[2024-06-16 13:28:06] error:    zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-06-16 13:28:06] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-06-16 13:28:06] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-06-16 13:28:07] info:     zh:ember:uart:ash: ======== ASH connected ========
[2024-06-16 13:28:07] info:     zh:ember:uart:ash: ======== ASH started ========
[2024-06-16 13:28:07] info:     zh:ember:ezsp: ======== EZSP started ========
[2024-06-16 13:28:09] warning:  zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e]
[2024-06-16 13:28:09] error:    zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE.
[2024-06-16 13:28:09] error:    zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR
[2024-06-16 13:28:09] error:    zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR.
[2024-06-16 13:28:09] error:    zh:ember: !!! NCP FATAL ERROR reason=HOST_FATAL_ERROR. ATTEMPTING RESET... !!!
[2024-06-16 13:28:09] info:     zh:ember:queue: Request dispatching stopped; queue=0 priorityQueue=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash: ASH COUNTERS since last clear:
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Total frames: RX=2, TX=3
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Cancelled   : RX=1, TX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   DATA frames : RX=0, TX=1
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   DATA bytes  : RX=0, TX=4
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Retry frames: RX=0, TX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   ACK frames  : RX=0, TX=1
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   NAK frames  : RX=0, TX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   nRdy frames : RX=0, TX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   CRC errors      : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Comm errors     : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Length < minimum: RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Length > maximum: RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Bad controls    : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Bad lengths     : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Bad ACK numbers : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Out of buffers  : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Retry dupes     : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   Out of sequence : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash:   ACK timeouts    : RX=0
[2024-06-16 13:28:09] info:     zh:ember:uart:ash: ======== ASH stopped ========
[2024-06-16 13:28:09] info:     zh:ember:ezsp: ======== EZSP stopped ========
[2024-06-16 13:28:09] info:     zh:ember: ======== Ember Adapter Stopped ========
[2024-06-16 13:28:09] info:     zh:ember: ======== Ember Adapter Starting ========
[2024-06-16 13:28:09] info:     zh:ember:ezsp: ======== EZSP starting ========
[2024-06-16 13:28:09] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-06-16 13:28:09] info:     zh:ember:uart:ash: Socket ready
[2024-06-16 13:28:09] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-06-16 13:28:10] info:     zh:ember:uart:ash: ======== ASH connected ========
[2024-06-16 13:28:10] info:     zh:ember:uart:ash: ======== ASH started ========
[2024-06-16 13:28:10] info:     zh:ember:ezsp: ======== EZSP started ========
[2024-06-16 13:28:11] info:     zh:ember: [STACK STATUS] Network up.
[2024-06-16 13:28:11] info:     zh:ember: [INIT TC] NCP network matches config.
[2024-06-16 13:28:11] info:     zh:ember: [CONCENTRATOR] Started source route discovery. 1248ms until next broadcast.
[2024-06-16 13:28:11] info:     zh:ember:queue: Request dispatching started.

Z2M Instance 1 retry (same for instance 2)

[13:30:31] INFO: Starting Zigbee2MQTT...
[2024-06-16 13:30:32] info:     z2m: Logging to console, file (filename: log.log)
[2024-06-16 13:30:32] info:     z2m: Starting Zigbee2MQTT version 1.38.0 (commit #unknown)
[2024-06-16 13:30:32] info:     z2m: Starting zigbee-herdsman (0.49.2)
[2024-06-16 13:30:33] info:     zh:ember: Using default stack config.
[2024-06-16 13:30:33] info:     zh:ember: ======== Ember Adapter Starting ========
[2024-06-16 13:30:33] info:     zh:ember:ezsp: ======== EZSP starting ========
[2024-06-16 13:30:33] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-06-16 13:30:33] info:     zh:ember:uart:ash: Socket ready
[2024-06-16 13:30:33] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-06-16 13:30:33] error:    zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-06-16 13:30:33] error:    zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR
[2024-06-16 13:30:33] error:    zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-06-16 13:30:33] error:    zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-06-16 13:30:33] error:    zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-06-16 13:30:33] error:    zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-06-16 13:30:33] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-06-16 13:30:33] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-06-16 13:30:34] info:     zh:ember:uart:ash: ======== ASH connected ========
[2024-06-16 13:30:34] info:     zh:ember:uart:ash: ======== ASH started ========
[2024-06-16 13:30:34] info:     zh:ember:ezsp: ======== EZSP started ========

After a reboot of both coordinators, it worked again...

domoblog commented 3 months ago

Hello, any news about this issue or workaround to apply please ? Same issue on my lab with last firmware of SLZB-06M.

works fine when I switch to adapter: ezsp

but still BROADCAST error in adapter: ember mode. Z2M started but not possible to join any devices.

thank you

kklepacz commented 3 months ago

not sure if it is connected but I struggle with daily backups with the same error. What I'm doing is a Proxmox container backup with mode = STOP meaning it is shutdown and started again after backup. This always ends up with:

Jun 17 12:56:01 zigbee2mqtt npm[316]: [2024-06-17 12:56:01] error:         zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
Jun 17 12:56:01 zigbee2mqtt npm[316]: [2024-06-17 12:56:01] error:         zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR
Jun 17 12:56:01 zigbee2mqtt npm[316]: [2024-06-17 12:56:01] error:         zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.

Doing manual reboot again solves the issue:

Jun 17 13:00:11 zigbee2mqtt npm[316]: [2024-06-17 13:00:11] info:         zh:ember:uart:ash: ======== ASH connected ========
Jun 17 13:00:11 zigbee2mqtt npm[316]: [2024-06-17 13:00:11] info:         zh:ember:uart:ash: ======== ASH started ========

Not sure what is a difference between those 2 reboots (backup vs manual)

Using: Zigbee2MQTT version 1.38.0 Coordinator type EmberZNet Coordinator revision 7.4.1 [GA] Frontend version 0.7.1

sblantipodi commented 3 months ago

I have same issue here: zh:ember: Delivery of BROADCAST failed for "65533"

Using SkyConnect on 7.4.1, 7.4.2, 7.4.3 firmware and same issue. I tried clearing everything manually, database file etc. Using the docker container of zigbee2mqtt 1.38

With EZSP driver it works no problem, with Ember I can't pair new devices due to that error. Paired devices continue to work on Ember if I pair them before with EZSP.

Dominator86 commented 3 months ago

After rebooting HA today my zigbee devices became unresponsive and "Delivery of BROADCAST failed" errors kept popping up. The only way to "fix" it was reverting back to ezsp. It's weird because I've been running ember for several weeks now and it has already survived a reboot without issues, so no idea why this time was different. Hardware is a Sonoff Dongle-E with FW 7.4.2.0 and I'm using the Z2M HA addon if that matters.

sblantipodi commented 3 months ago

at this point is pretty evident that Ember is not ready for the release, I don't get why they consider EZSP deprecated :)

alainsch commented 3 months ago

for my "production" environment, I'm switching back to EZSP 'till ember problems are fixed.

    public async start(): Promise<StartResult> {
        const logEzspDeprecated = (): void => {
            const message = `Deprecated driver 'ezsp' currently in use, 'ember' will become the officially supported EmberZNet ` +
                `driver in next release. If using Zigbee2MQTT see https://github.com/Koenkk/zigbee2mqtt/discussions/21462`;
            logger.warning(message, NS);
        };
        logEzspDeprecated();
        this.deprecatedTimer = setInterval(logEzspDeprecated, 60 * 60 * 1000); // Every 60 mins
        return this.driver.startup();
    }

Maybe in a next release you could set a higher value for the timer to call the logEzspDeprecated() method? A warning every hour is a bit overkill I think. Once a day or only on startup?