search

Koenkk / zigbee2mqtt

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

Dongle-E 7.4.2 ember initial startup errors and broadcast error #22398

Closed supaeasy closed 1 day ago

supaeasy commented 2 weeks ago

What happened?

Yesterday I updated my Sonoff Dongle-E from 7.4.1 to 7.4.2 and changed serial: ezsp to serial:ember.

My first issue "solves" itself by retrying from the addon itself. After the end of this message, there are no more errors concerning this. These errors are reproducable when I restart the addon:

[10:45:12] INFO: Preparing to start...
[10:45:12] INFO: Socat not enabled
[10:45:13] INFO: Starting Zigbee2MQTT...
[2024-05-02 10:45:17] error:    zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-05-02 10:45:17] error:    zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR
[2024-05-02 10:45:19] warning:  zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e]
[2024-05-02 10:45:19] error:    zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE.
[2024-05-02 10:45:19] error:    zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR
[2024-05-02 10:45:32] error:    zh:ember:ezsp: ERROR Transaction failure; status=undefined. Last: [FRAME: ID=0:"VERSION" Seq=0 Len=4].
[2024-05-02 10:45:32] error:    zh:ember: !!! NCP FATAL ERROR reason=undefined. ATTEMPTING RESET... !!!
[2024-05-02 10:45:32] error:    z2m: Error while starting zigbee-herdsman
[2024-05-02 10:45:32] error:    z2m: Failed to start zigbee
[2024-05-02 10:45:32] error:    z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
[2024-05-02 10:45:32] error:    z2m: Exiting...
[2024-05-02 10:45:32] error:    z2m: Error: 
    at Ezsp.ezspVersion (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:1301:19)
    at EmberAdapter.emberVersion (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1642:66)
    at EmberAdapter.initEzsp (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:802:9)
    at EmberAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:2660:24)
    at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:124:29)
    at Zigbee.start (/app/lib/zigbee.ts:62:27)
    at Controller.start (/app/lib/controller.ts:108:27)
    at start (/app/index.js:107:5)
[10:45:34] INFO: Preparing to start...
[10:45:35] INFO: Socat not enabled
[10:45:35] INFO: Starting Zigbee2MQTT...

There is another error that I just don't understand. Can you help me determining what it means? It happens once in a while, not very often. Unfortunately my logs were overwritten in the meantime but I think it was 4 times in the last 7 hours. All values except "sequence" value stay the same with every message. How can I find out what 65533 and/or clusterId is referring to?

error: zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":6,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":165} messageTag=255]

What did you expect to happen?

No errors occur

How to reproduce it (minimal and precise)

Restart addon / wait some time

Zigbee2MQTT version

1.37.0-1

Adapter firmware version

7.4.2 [GA]

Adapter

Sonoff Dongle-E

Setup

Add-on on Home Assistant OS

Debug log

No response

alainsch commented 2 weeks ago

Same problem here:

[2024-05-02 13:12:02] 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]

coordinator is a SmartLight SLZB06-M with firmware 2.0.18 and zigbee firmware 20240408

wastez commented 2 weeks ago

@supaeasy The problem is the connection to your stick, it’s not working and run in a timeout. Can you show your serial configuration? Did you install firmware with a other baudrate? Can you access the device from cli? Or a probe with silabs universal flasher?

supaeasy commented 2 weeks ago

I am running HA in a VM only Synology NAS. Could there be a problem?

The stick is flashed via Silabs Flasher Addon in HA. I didn't change the baud rate, just changed the version number in flashers config. Baud rate is 115200.

Serial config:

adapter: ember
port: >-
  /dev/serial/by-id/usb-ITEAD_SONOFF_Zigbee_3.0_USB_Dongle_Plus_V2_20220811162453-if00

I don't understand what you mean with can I access the device from cli? And also: after the error everything is working fine. I am just wondering what these errors mean.

wastez commented 2 weeks ago

ok I read right now that it is working after the error. for some reason it can’t access the device on the first startup.

Nerivec commented 2 weeks ago

Delivery of broadcast can be problematic at times. It's usually a device that it failed to reached at that time. 65532/65533/65535 is just the "special" broadcast address, to address only routers, only devices with receiver on, or all devices.

Both of your cases shouldn't be a problem.

As for the startup error (on first try), it's already under investigation 😉

supaeasy commented 2 weeks ago

Oh ok it might be a router device (IKEA Tradfri plug) that is left offline intentionally at times. Will try to leave it on and see if the error persists. I do get a warning about this as well but didn't think it would corellate. If I am not alone with the startup error that's fine for me. Thank you.

diegocade1 commented 1 week ago

Same problem Received unexpected reset from NCP, with reason=RESET_SOFTWARE, but mine cant start it just keep showing the same error.

[10:00:13] INFO: Starting Zigbee2MQTT... [2024-05-03 10:00:14] info: z2m: Logging to console, file (filename: log.log) [2024-05-03 10:00:14] info: z2m: Starting Zigbee2MQTT version 1.37.0 (commit #unknown) [2024-05-03 10:00:14] info: z2m: Starting zigbee-herdsman (0.45.0) [2024-05-03 10:00:14] info: zh:ember: ======== Ember Adapter Starting ======== [2024-05-03 10:00:14] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-05-03 10:00:14] info: zh:ember:uart:ash: ======== ASH NCP reset ======== [2024-05-03 10:00:14] info: zh:ember:uart:ash: Socket ready [2024-05-03 10:00:14] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-05-03 10:00:17] info: zh:ember:uart:ash: ======== ASH NCP reset ======== [2024-05-03 10:00:17] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-05-03 10:00:17] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-05-03 10:00:17] info: zh:ember:uart:ash: ======== ASH started ======== [2024-05-03 10:00:17] info: zh:ember:ezsp: ======== EZSP started ======== [2024-05-03 10:00:21] warning: zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e] [2024-05-03 10:00:21] error: zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE. [2024-05-03 10:00:21] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR [2024-05-03 10:00:32] error: zh:ember:ezsp: ERROR Transaction failure; status=undefined. Last: [FRAME: ID=0:"VERSION" Seq=0 Len=4]. [2024-05-03 10:00:32] error: zh:ember: !!! NCP FATAL ERROR reason=undefined. ATTEMPTING RESET... !!! [2024-05-03 10:00:32] info: zh:ember:uart:ash: ASH COUNTERS since last clear: [2024-05-03 10:00:32] info: zh:ember:uart:ash: Total frames: RX=2, TX=3 [2024-05-03 10:00:32] info: zh:ember:uart:ash: Cancelled : RX=1, TX=0 [2024-05-03 10:00:32] info: zh:ember:uart:ash: DATA frames : RX=0, TX=1 [2024-05-03 10:00:32] info: zh:ember:uart:ash: DATA bytes : RX=0, TX=4 [2024-05-03 10:00:32] info: zh:ember:uart:ash: Retry frames: RX=0, TX=0 [2024-05-03 10:00:32] info: zh:ember:uart:ash: ACK frames : RX=0, TX=1 [2024-05-03 10:00:32] info: zh:ember:uart:ash: NAK frames : RX=0, TX=0 [2024-05-03 10:00:32] info: zh:ember:uart:ash: nRdy frames : RX=0, TX=0 [2024-05-03 10:00:32] info: zh:ember:uart:ash: CRC errors : RX=0 [2024-05-03 10:00:32] info: zh:ember:uart:ash: Comm errors : RX=0 [2024-05-03 10:00:32] info: zh:ember:uart:ash: Length < minimum: RX=0 [2024-05-03 10:00:32] info: zh:ember:uart:ash: Length > maximum: RX=0 [2024-05-03 10:00:32] info: zh:ember:uart:ash: Bad controls : RX=0 [2024-05-03 10:00:32] info: zh:ember:uart:ash: Bad lengths : RX=0 [2024-05-03 10:00:32] info: zh:ember:uart:ash: Bad ACK numbers : RX=0 [2024-05-03 10:00:32] info: zh:ember:uart:ash: Out of buffers : RX=0 [2024-05-03 10:00:32] info: zh:ember:uart:ash: Retry dupes : RX=0 [2024-05-03 10:00:32] info: zh:ember:uart:ash: Out of sequence : RX=0 [2024-05-03 10:00:32] info: zh:ember:uart:ash: ACK timeouts : RX=0 [2024-05-03 10:00:32] info: zh:ember:uart:ash: ======== ASH stopped ======== [2024-05-03 10:00:32] info: zh:ember:ezsp: ======== EZSP stopped ======== [2024-05-03 10:00:32] info: zh:ember: ======== Ember Adapter Stopped ======== [2024-05-03 10:00:32] error: z2m: Error while starting zigbee-herdsman [2024-05-03 10:00:32] error: z2m: Failed to start zigbee [2024-05-03 10:00:32] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions [2024-05-03 10:00:32] error: z2m: Exiting... [2024-05-03 10:00:32] error: z2m: Error: at Ezsp.ezspVersion (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:1301:19) at EmberAdapter.emberVersion (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1642:66) at EmberAdapter.initEzsp (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:802:9) at EmberAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:2660:24) at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:124:29) at Zigbee.start (/app/lib/zigbee.ts:62:27) at Controller.start (/app/lib/controller.ts:108:27) at start (/app/index.js:107:5)

different serial configuration:

port: tcp://core-silabs-multiprotocol:9999 adapter: ember

Ciqsky commented 1 week ago

Help! I have a problem. I have flashed my ITEAD_SONOFF_Zigbee_3.0_USB_Dongle_Plus_V2 with ncp-uart-hw-v7.4.2.0-zbdonglee-230400.gbl How I can reflash with 115200? I flashed with windows with website but now dongle can't connect anymore. When I start zigbee2mqtt with "ember" I have: [2024-05-04 23:19:42] debug: zh:ember:uart:ash: ---> [FRAME type=RST] [2024-05-04 23:19:42] debug: zh:ember:uart:ash: Waiting for RSTACK... 0/2500 [2024-05-04 23:19:42] debug: zh:ember:uart:ash: Waiting for RSTACK... 100/2500 [2024-05-04 23:19:42] debug: zh:ember:uart:ash: Waiting for RSTACK... 200/2500 [2024-05-04 23:19:42] debug: zh:ember:uart:ash: Waiting for RSTACK... 300/2500 [2024-05-04 23:19:42] debug: zh:ember:uart:ash: Waiting for RSTACK... 400/2500 [2024-05-04 23:19:43] debug: zh:ember:uart:ash: Waiting for RSTACK... 500/2500 [2024-05-04 23:19:43] debug: zh:ember:uart:ash: Waiting for RSTACK... 600/2500 [2024-05-04 23:19:43] debug: zh:ember:uart:ash: Waiting for RSTACK... 700/2500 [2024-05-04 23:19:43] debug: zh:ember:uart:ash: Waiting for RSTACK... 800/2500 [2024-05-04 23:19:43] debug: zh:ember:uart:ash: Waiting for RSTACK... 900/2500 [2024-05-04 23:19:43] debug: zh:ember:uart:ash: Waiting for RSTACK... 1000/2500 [2024-05-04 23:19:43] debug: zh:ember:uart:ash: Waiting for RSTACK... 1100/2500 [2024-05-04 23:19:43] debug: zh:ember:uart:ash: Waiting for RSTACK... 1200/2500 [2024-05-04 23:19:43] debug: zh:ember:uart:ash: Waiting for RSTACK... 1300/2500 [2024-05-04 23:19:43] debug: zh:ember:uart:ash: Waiting for RSTACK... 1400/2500 [2024-05-04 23:19:44] debug: zh:ember:uart:ash: Waiting for RSTACK... 1500/2500 [2024-05-04 23:19:44] debug: zh:ember:uart:ash: Waiting for RSTACK... 1600/2500 [2024-05-04 23:19:44] debug: zh:ember:uart:ash: Waiting for RSTACK... 1700/2500 [2024-05-04 23:19:44] debug: zh:ember:uart:ash: Waiting for RSTACK... 1800/2500 [2024-05-04 23:19:44] debug: zh:ember:uart:ash: Waiting for RSTACK... 1900/2500 [2024-05-04 23:19:44] debug: zh:ember:uart:ash: Waiting for RSTACK... 2000/2500 [2024-05-04 23:19:44] debug: zh:ember:uart:ash: Waiting for RSTACK... 2100/2500 [2024-05-04 23:19:44] debug: zh:ember:uart:ash: Waiting for RSTACK... 2200/2500 [2024-05-04 23:19:44] debug: zh:ember:uart:ash: Waiting for RSTACK... 2300/2500 [2024-05-04 23:19:44] debug: zh:ember:uart:ash: Waiting for RSTACK... 2400/2500 [2024-05-04 23:19:45] error: z2m: Error while starting zigbee-herdsman [2024-05-04 23:19:45] error: z2m: Failed to start zigbee [2024-05-04 23:19:45] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions [2024-05-04 23:19:45] error: z2m: Exiting... [2024-05-04 23:19:45] error: z2m: Error: Failed to start EZSP layer with status=HOST_FATAL_ERROR. at EmberAdapter.initEzsp (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:798:19) at EmberAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:2660:24) at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:124:29) at Zigbee.start (/app/lib/zigbee.ts:62:27) at Controller.start (/app/lib/controller.ts:108:27) at start (/app/index.js:107:5)

Zigbee2MQTT version: 1.37.0-1

Nerivec commented 1 week ago

@Ciqsky The webflasher doesn't handle 230400. You will have to flash it with https://github.com/NabuCasa/universal-silabs-flasher/ To get Z2M to work with a baudrate that is not 115200, you have to set the setting:

serial:
  adapter: ember
  baudrate: 230400

115200 is the most tested baudrate though.

@diegocade1 Multiprotocol is not supported since HA froze its development.

Ciqsky commented 1 week ago

I have tried but unfortunately.

adapter: ember baudrate: 230400 port: >- /dev/serial/by-id/usb-ITEAD_SONOFF_Zigbee_3.0_USB_Dongle_Plus_V2_20230525150239-if00

[23:55:15] INFO: Preparing to start... [23:55:16] INFO: Socat not enabled [23:55:18] INFO: Starting Zigbee2MQTT... [2024-05-04 23:55:23] info: z2m: Logging to console, file (filename: log.log) [2024-05-04 23:55:28] debug: z2m: Loaded state from file /config/zigbee2mqtt/state.json [2024-05-04 23:55:28] info: z2m: Starting Zigbee2MQTT version 1.37.0 (commit #unknown) [2024-05-04 23:55:28] info: z2m: Starting zigbee-herdsman (0.45.0) [2024-05-04 23:55:28] debug: z2m: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backupPath":"/config/zigbee2mqtt/coordinator_backup.json","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","databasePath":"/config/zigbee2mqtt/database.db","network":{"channelList":[11],"extendedPanID":[221,221,221,221,221,221,221,221],"networkKey":"HIDDEN","panID":6754},"serialPort":{"adapter":"ember","baudRate":230400,"path":"/dev/serial/by-id/usb-ITEAD_SONOFF_Zigbee_3.0_USB_Dongle_Plus_V2_20230525150239-if00"}}' [2024-05-04 23:55:29] debug: zh:adapter: Failed to validate path: 'Error: spawn udevadm ENOENT' [2024-05-04 23:55:29] debug: zh:ember: Using delay=5. [2024-05-04 23:55:29] debug: zh:controller: Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13],"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11]},"serialPort":{"baudRate":230400,"path":"/dev/serial/by-id/usb-ITEAD_SONOFF_Zigbee_3.0_USB_Dongle_Plus_V2_20230525150239-if00","adapter":"ember"},"databasePath":"/config/zigbee2mqtt/database.db","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","backupPath":"/config/zigbee2mqtt/coordinator_backup.json","adapter":{"disableLED":false,"concurrent":null,"delay":null}}' [2024-05-04 23:55:29] info: zh:ember: ======== Ember Adapter Starting ======== [2024-05-04 23:55:29] debug: zh:ember: Starting EZSP with stack configuration: "default". [2024-05-04 23:55:29] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-05-04 23:55:29] info: zh:ember:uart:ash: ======== ASH NCP reset ======== [2024-05-04 23:55:29] info: zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control. [2024-05-04 23:55:29] debug: zh:ember:uart:ash: Opening serial port with {"path":"/dev/serial/by-id/usb-ITEAD_SONOFF_Zigbee_3.0_USB_Dongle_Plus_V2_20230525150239-if00","baudRate":230400,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true} [2024-05-04 23:55:29] info: zh:ember:uart:ash: Serial port opened [2024-05-04 23:55:29] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-05-04 23:55:29] debug: zh:ember:uart:ash: ---> [FRAME type=RST] [2024-05-04 23:55:29] debug: zh:ember:uart:ash: Waiting for RSTACK... 0/2500 [2024-05-04 23:55:29] debug: zh:ember:uart:ash: Waiting for RSTACK... 100/2500 [2024-05-04 23:55:29] debug: zh:ember:uart:ash: Waiting for RSTACK... 200/2500 [2024-05-04 23:55:29] debug: zh:ember:uart:ash: Waiting for RSTACK... 300/2500 [2024-05-04 23:55:29] debug: zh:ember:uart:ash: Waiting for RSTACK... 400/2500 [2024-05-04 23:55:29] debug: zh:ember:uart:ash: Waiting for RSTACK... 500/2500 [2024-05-04 23:55:29] debug: zh:ember:uart:ash: Waiting for RSTACK... 600/2500 [2024-05-04 23:55:29] debug: zh:ember:uart:ash: Waiting for RSTACK... 700/2500 [2024-05-04 23:55:30] debug: zh:ember:uart:ash: Waiting for RSTACK... 800/2500 [2024-05-04 23:55:30] debug: zh:ember:uart:ash: Waiting for RSTACK... 900/2500 [2024-05-04 23:55:30] debug: zh:ember:uart:ash: Waiting for RSTACK... 1000/2500 ..... [2024-05-04 23:57:52] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=28 Len=6] [2024-05-04 23:57:52] debug: zh:ember: [EzspConfigId] SET "MULTICAST_TABLE_SIZE" TO "16" with status=SUCCESS. [2024-05-04 23:57:52] debug: zh:ember:ezsp: ===> [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=29 Len=10] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-05-04 23:57:52] debug: zh:ember:ezsp: <=== [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=29 Len=9] [2024-05-04 23:57:52] debug: zh:ember:ezsp: ===> [FRAME: ID=2:"ADD_ENDPOINT" Seq=30 Len=63] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-05-04 23:57:52] debug: zh:ember:ezsp: <=== [FRAME: ID=2:"ADD_ENDPOINT" Seq=30 Len=6] [2024-05-04 23:57:52] debug: zh:ember: Registered endpoint "1" with status=SUCCESS. [2024-05-04 23:57:52] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=31 Len=10] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7] Added to rxQueue [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-05-04 23:57:52] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=31 Len=6] [2024-05-04 23:57:52] debug: zh:ember: Registered multicast table entry: {"multicastId":0,"endpoint":1,"networkIndex":0}. [2024-05-04 23:57:52] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=32 Len=10] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-05-04 23:57:52] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=32 Len=6] [2024-05-04 23:57:52] debug: zh:ember: Registered multicast table entry: {"multicastId":901,"endpoint":1,"networkIndex":0}. [2024-05-04 23:57:52] debug: zh:ember:ezsp: ===> [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=33 Len=10] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-05-04 23:57:52] debug: zh:ember:ezsp: <=== [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=33 Len=9] [2024-05-04 23:57:52] debug: zh:ember:ezsp: ===> [FRAME: ID=2:"ADD_ENDPOINT" Seq=34 Len=17] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2] Added to rxQueue [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-05-04 23:57:52] debug: zh:ember:ezsp: <=== [FRAME: ID=2:"ADD_ENDPOINT" Seq=34 Len=6] [2024-05-04 23:57:52] debug: zh:ember: Registered endpoint "242" with status=SUCCESS. [2024-05-04 23:57:52] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=35 Len=10] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-05-04 23:57:52] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=35 Len=6] [2024-05-04 23:57:52] debug: zh:ember: Registered multicast table entry: {"multicastId":2948,"endpoint":242,"networkIndex":0}. [2024-05-04 23:57:52] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=36 Len=7] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4] Added to rxQueue [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-05-04 23:57:52] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=36 Len=6] [2024-05-04 23:57:52] debug: zh:ember: [EzspPolicyId] SET "TC_KEY_REQUEST_POLICY" TO "81" with status=SUCCESS. [2024-05-04 23:57:52] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=37 Len=7] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-05-04 23:57:52] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=37 Len=6] [2024-05-04 23:57:52] debug: zh:ember: [EzspPolicyId] SET "APP_KEY_REQUEST_POLICY" TO "96" with status=SUCCESS. [2024-05-04 23:57:52] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=38 Len=7] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-05-04 23:57:52] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=38 Len=6] [2024-05-04 23:57:52] debug: zh:ember: [EzspPolicyId] SET "TRUST_CENTER_POLICY" TO "3" with status=SUCCESS. [2024-05-04 23:57:52] debug: zh:ember:ezsp: ===> [FRAME: ID=23:"NETWORK_INIT" Seq=39 Len=7] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-05-04 23:57:52] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7] Added to rxQueue [2024-05-04 23:57:52] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-05-04 23:57:52] debug: zh:ember:ezsp: <=== [FRAME: ID=23:"NETWORK_INIT" Seq=39 Len=6] [2024-05-04 23:57:52] debug: zh:ember: [INIT TC] Network init status=NOT_JOINED. [2024-05-04 23:57:52] error: z2m: Error while starting zigbee-herdsman [2024-05-04 23:57:52] error: z2m: Failed to start zigbee [2024-05-04 23:57:52] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions [2024-05-04 23:57:52] error: z2m: Exiting... [2024-05-04 23:57:53] error: z2m: Error: [BACKUP] Current backup file is from an unsupported EZSP version (min: 12). at EmberAdapter.getStoredBackup (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1340:23) at EmberAdapter.initTrustCenter (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1131:33) at EmberAdapter.initEzsp (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:813:19) at EmberAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:2660:24) at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:124:29) at Zigbee.start (/app/lib/zigbee.ts:62:27) at Controller.start (/app/lib/controller.ts:108:27) at start (/app/index.js:107:5)

I have tried with

universal-silabs-flasher --device /dev/ttyACM0 probe

from RPI4 terminal into HASSOS but

I have ERROR: failed to probe running application type

same if I try to flash with ncp-uart-hw-v7.4.2.0-zbdonglee-115200.gbl

universal-silabs-flasher --device /dev/ttyACM0 flash --firmware ncp-uart-hw-v7.4.2.0-zbdonglee-115200.gbl --allow-cross-flashing

I have tried also with sudo but same error

Ciqsky commented 1 week ago

I don't have any other linux OS with windows is possible?

Nerivec commented 1 week ago

Flashing looks to have worked since you were able to start. However: [BACKUP] Current backup file is from an unsupported EZSP version (min: 12). You need to remove your coordinator_backup.json file in you zigbee2mqtt folder. It was made with an old ezsp version.

Ciqsky commented 1 week ago

YESSSSS! Works! THANK YOU!! But I have Zigbee2MQTT empty :( - no sensor ....I have to re-insert all sensor??

Ciqsky commented 1 week ago

I have tried to copy into coordinator_backup.json from old backup (not deleted) pan_id extended_pan_id "network_key": "key": "sequence_number": "frame_counter":

and restart z2mqtt ...but nothing...

I receive many messages with [2024-05-05 00:57:14] debug: zh:controller: Data is from unknown device with address '29674', skipping...

...into configuration I have all sensors defined

Nerivec commented 1 week ago

Looks like you might have erased your adapter at some point during your firmware troubles. That's what this line means (adapter has no network): [INIT TC] Network init status=NOT_JOINED.

You might be able to restore it by playing with the configuration manually, but I'd advise to re-pair everything with a clean network now that you know your zigbee2mqtt starts properly. Since I'm not exactly sure what you did and how, you might end up with more troubles if you try to restore this manually. You can set this in configuration.yaml to ensure a clean and secure network; just pick your preferred channel.

advanced:
  channel: 20
  network_key: GENERATE
  pan_id: GENERATE
  ext_pan_id: GENERATE

Then start Z2M again, and start pairing devices.

remidebette commented 1 week ago

If it can help someone, I also had no idea about what baudrate to use and started with 230400, which left me unable to use the webflasher. After reading a few articles, here is the command that allowed me to fix my Sonoff dongle E (on mac, but linux should be similar):

# Find the device with 
ls /dev/tty* | grep usb
/dev/tty.usbserial-202308300932321

# Flash
universal-silabs-flasher --device /dev/tty.usbserial-202308300932321 --bootloader-reset sonoff flash --firmware ncp-uart-hw-v7.4.2.0-zbdonglee-115200.gbl

Source: described for Windows: https://github.com/darkxst/silabs-firmware-builder/issues/56#issuecomment-1964240074

Ciqsky commented 1 week ago

Sembra che potresti aver cancellato l'adattatore ad un certo punto durante i problemi del firmware. Questo è il significato di questa riga (l'adattatore non ha rete): [INIT TC] Network init status=NOT_JOINED.

Potresti riuscire a ripristinarlo giocando manualmente con la configurazione, ma ti consiglio di riassociare il tutto con una rete pulita ora che sai che zigbee2mqtt si avvia correttamente. Poiché non sono esattamente sicuro di cosa hai fatto e come, potresti riscontrare più problemi se provi a ripristinarlo manualmente. Puoi impostarlo configuration.yamlper garantire una rete pulita e sicura ; scegli semplicemente il tuo canale preferito.

advanced:
  channel: 20
  network_key: GENERATE
  pan_id: GENERATE
  ext_pan_id: GENERATE

Quindi avvia nuovamente Z2M e inizia ad associare i dispositivi.

I have reassociated all sensor and now works. Thank you all for assistance!

Nerivec commented 1 week ago

PS: darkxst webflasher now supports baudrate 230400, in case any of you want to migrate back to 115200 (the more tested one) you should be able to do it from there directly. If you do, make sure to change the setting in z2m too.

Ricc68 commented 1 week ago

@Nerivec, if you are interested in a debug log of the first start crash, I'm attaching it. log.log

XFNeo commented 1 week ago

Hi! I have the same issue on Dongle-E with 7.4.2(ncp-uart-hw-v7.4.2.0-zbdonglee-115200.gbl) firmware and z2m 1.37.0 with adapter: ember. Z2m container starts only from second time.

Logs adapter: ember 
[2024-05-08 13:26:32] info:     zh:ember:ezsp: ======== EZSP starting ========
[2024-05-08 13:26:32] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-05-08 13:26:32] info:     zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control.
[2024-05-08 13:26:32] info:     zh:ember:uart:ash: Serial port opened
[2024-05-08 13:26:32] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-05-08 13:26:32] error:    zh:ember:uart:ash: Received frame with CRC error
[2024-05-08 13:26:32] error:    zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-05-08 13:26:32] error:    zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR
[2024-05-08 13:26:32] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-05-08 13:26:32] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-05-08 13:26:33] info:     zh:ember:uart:ash: ======== ASH connected ========
[2024-05-08 13:26:33] info:     zh:ember:uart:ash: ======== ASH started ========
[2024-05-08 13:26:33] info:     zh:ember:ezsp: ======== EZSP started ========
[2024-05-08 13:26:34] warning:  zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e]
[2024-05-08 13:26:34] error:    zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE.
[2024-05-08 13:26:34] error:    zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR
[2024-05-08 13:26:47] error:    zh:ember:ezsp: ERROR Transaction failure; status=undefined. Last: [FRAME: ID=0:"VERSION" Seq=0 Len=4].
[2024-05-08 13:26:47] error:    zh:ember: !!! NCP FATAL ERROR reason=undefined. ATTEMPTING RESET... !!!
[2024-05-08 13:26:47] info:     zh:ember:uart:ash: ASH COUNTERS since last clear:
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   Total frames: RX=2, TX=3
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   Cancelled   : RX=1, TX=0
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   DATA frames : RX=0, TX=1
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   DATA bytes  : RX=0, TX=4
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   Retry frames: RX=0, TX=0
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   ACK frames  : RX=0, TX=1
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   NAK frames  : RX=0, TX=0
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   nRdy frames : RX=0, TX=0
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   CRC errors      : RX=0
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   Comm errors     : RX=0
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   Length < minimum: RX=0
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   Length > maximum: RX=0
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   Bad controls    : RX=0
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   Bad lengths     : RX=0
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   Bad ACK numbers : RX=0
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   Out of buffers  : RX=0
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   Retry dupes     : RX=0
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   Out of sequence : RX=0
[2024-05-08 13:26:47] info:     zh:ember:uart:ash:   ACK timeouts    : RX=0
[2024-05-08 13:26:47] error:    z2m: Error while starting zigbee-herdsman
[2024-05-08 13:26:47] error:    z2m: Failed to start zigbee
[2024-05-08 13:26:47] error:    z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
[2024-05-08 13:26:47] error:    z2m: Exiting...
[2024-05-08 13:26:48] error:    z2m: Error: 
    at Ezsp.ezspVersion (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:1301:19)
    at EmberAdapter.emberVersion (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1642:66)
    at EmberAdapter.initEzsp (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:802:9)
    at EmberAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:2660:24)
    at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:124:29)
    at Zigbee.start (/app/lib/zigbee.ts:62:27)
    at Controller.start (/app/lib/controller.ts:108:27)
    at start (/app/index.js:107:5)
Using '/app/data' as data directory
[2024-05-08 13:26:49] info:     z2m: Logging to console, file (filename: log.log)
[2024-05-08 13:26:50] info:     z2m: Starting Zigbee2MQTT version 1.37.0 (commit #46f34c8)
[2024-05-08 13:26:50] info:     z2m: Starting zigbee-herdsman (0.45.0)
[2024-05-08 13:26:50] info:     zh:ember: ======== Ember Adapter Starting ========
[2024-05-08 13:26:50] info:     zh:ember:ezsp: ======== EZSP starting ========
[2024-05-08 13:26:50] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-05-08 13:26:50] info:     zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control.
[2024-05-08 13:26:50] info:     zh:ember:uart:ash: Serial port opened
[2024-05-08 13:26:50] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-05-08 13:26:51] info:     zh:ember:uart:ash: ======== ASH connected ========
[2024-05-08 13:26:51] info:     zh:ember:uart:ash: ======== ASH started ========
[2024-05-08 13:26:51] info:     zh:ember:ezsp: ======== EZSP started ========
[2024-05-08 13:26:51] info:     zh:ember: [STACK STATUS] Network up.
[2024-05-08 13:26:51] info:     zh:ember: [INIT TC] NCP network matches config.
[2024-05-08 13:26:51] info:     zh:ember: [CONCENTRATOR] Started source route discovery. 1249ms until next broadcast.
...
[2024-05-08 13:26:51] info:     z2m: Zigbee: disabling joining new devices.
[2024-05-08 13:26:51] info:     z2m: Connecting to MQTT server at mqtt://mosquitto
[2024-05-08 13:26:51] info:     z2m: Connected to MQTT server
[2024-05-08 13:26:52] info:     z2m: Started frontend on port 8080
[2024-05-08 13:26:52] info:     z2m: Zigbee2MQTT started!
Also a lot of logs like below during work: warning: zh:ember:ezsp: Received network/route error ROUTE_ERROR_MANY_TO_ONE_ROUTE_FAILURE for "2428".

When I use adapter: ezsp I have another errors on startup:

Logs adapter: ezsp 
[2024-05-08 13:12:43] error:    zh:ezsp:uart: <-- CRC error: bd7e|bd|ffff
[2024-05-08 13:12:43] error:    zh:ezsp:uart: Error while parsing to NpiFrame 'Error: <-- CRC error: bd7e|bd|ffff
    at Frame.checkCRC (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/frame.ts:87:19)
    at SerialDriver.onParsed (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:169:19)
    at Parser.emit (node:events:517:28)
    at Parser._transform (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/parser.ts:49:26)
    at Parser.Transform._write (node:internal/streams/transform:175:8)
    at writeOrBuffer (node:internal/streams/writable:392:12)
    at _write (node:internal/streams/writable:333:10)
    at Parser.Writable.write (node:internal/streams/writable:337:10)
    at SerialPort.ondata (node:internal/streams/readable:809:22)
    at SerialPort.emit (node:events:517:28)'

P.S. But in both cases all devices are available and looks like z2m is working correctly.

LookInIs commented 1 week ago 
[11:38:20] INFO: Preparing to start...
[11:38:22] INFO: Socat not enabled
[11:38:25] INFO: Starting Zigbee2MQTT...
[2024-05-10 11:38:39] info:     z2m: Logging to console, file (filename: log.log)
[2024-05-10 11:38:39] info:     z2m: Starting Zigbee2MQTT version 1.37.1 (commit #unknown)
[2024-05-10 11:38:39] info:     z2m: Starting zigbee-herdsman (0.46.6)
[2024-05-10 11:38:40] info:     zh:ember: ======== Ember Adapter Starting ========
[2024-05-10 11:38:40] info:     zh:ember:ezsp: ======== EZSP starting ========
[2024-05-10 11:38:40] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-05-10 11:38:40] info:     zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control.
[2024-05-10 11:38:40] info:     zh:ember:uart:ash: Serial port opened
[2024-05-10 11:38:40] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-05-10 11:38:40] error:    zh:ember:uart:ash: Received frame with CRC error
[2024-05-10 11:38:40] error:    zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-05-10 11:38:40] error:    zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR
[2024-05-10 11:38:40] error:    zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-05-10 11:38:40] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-05-10 11:38:40] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-05-10 11:38:41] info:     zh:ember:uart:ash: ======== ASH connected ========
[2024-05-10 11:38:41] info:     zh:ember:uart:ash: ======== ASH started ========
[2024-05-10 11:38:41] info:     zh:ember:ezsp: ======== EZSP started ========
[2024-05-10 11:38:42] info:     zh:ember: [STACK STATUS] Network up.
[2024-05-10 11:38:42] info:     zh:ember: [INIT TC] NCP network matches config.
[2024-05-10 11:38:42] info:     zh:ember: [CONCENTRATOR] Started source route discovery. 1248ms until next broadcast.
[2024-05-10 11:38:42] info:     z2m: zigbee-herdsman started (resumed)
[2024-05-10 11:38:42] info:     z2m: Coordinator firmware version: '{"meta":{"build":0,"ezsp":13,"major":7,"minor":4,"patch":1,"revision":"7.4.1 [GA]","special":0,"type":170},"type":"EmberZNet"}'
[2024-05-10 11:38:42] info:     z2m: Currently 27 devices are joined:

"Error while parsing received frame, status=ASH_NCP_FATAL_ERROR"

this error occurs every time you start. I still can't figure out what the problem is and how to solve it.

Nerivec commented 6 days ago

Unfortunately some setups have a "messy" start, especially in virtualized environments it seems. The startup logic includes retries, up to five times, to get around that, per silabs recommendation. As long as it starts, you should be good to go, which yours seems to.

stich86 commented 5 days ago

Hi guys,

after i've tried to restore a Sonoff Dongle-E into a SLZB-06M (without success), the SLZB-06M seems to not work anymore. I can see the adapter, start\stop join but alwasy broadcast timeout and no way to join any new devices

here is the z2m log:

[2024-05-11 17:55:53] info:     z2m: Logging to console, file (filename: log.log)
[2024-05-11 17:55:53] info:     z2m: Starting Zigbee2MQTT version 1.37.1 (commit #ea39d86)
[2024-05-11 17:55:53] info:     z2m: Starting zigbee-herdsman (0.46.6)
[2024-05-11 17:55:53] info:     zh:ember: ======== Ember Adapter Starting ========
[2024-05-11 17:55:53] info:     zh:ember:ezsp: ======== EZSP starting ========
[2024-05-11 17:55:53] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-05-11 17:55:53] info:     zh:ember:uart:ash: Socket ready
[2024-05-11 17:55:53] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-05-11 17:55:54] info:     zh:ember:uart:ash: ======== ASH connected ========
[2024-05-11 17:55:54] info:     zh:ember:uart:ash: ======== ASH started ========
[2024-05-11 17:55:54] info:     zh:ember:ezsp: ======== EZSP started ========
[2024-05-11 17:55:54] warning:  zh:ember: [EzspConfigId] Failed to SET "ADDRESS_TABLE_SIZE" TO "16" with status=ERROR_OUT_OF_MEMORY. Firmware value will be used instead.
[2024-05-11 17:55:55] warning:  zh:ember: [EzspConfigId] Failed to SET "APS_UNICAST_MESSAGE_COUNT" TO "32" with status=ERROR_OUT_OF_MEMORY. Firmware value will be used instead.
[2024-05-11 17:55:55] warning:  zh:ember: [EzspConfigId] Failed to SET "NEIGHBOR_TABLE_SIZE" TO "26" with status=ERROR_OUT_OF_MEMORY. Firmware value will be used instead.
[2024-05-11 17:55:55] warning:  zh:ember: [EzspConfigId] Failed to SET "SOURCE_ROUTE_TABLE_SIZE" TO "200" with status=ERROR_INVALID_VALUE. Firmware value will be used instead.
[2024-05-11 17:55:55] warning:  zh:ember: [EzspConfigId] Failed to SET "MULTICAST_TABLE_SIZE" TO "16" with status=ERROR_OUT_OF_MEMORY. Firmware value will be used instead.
[2024-05-11 17:55:55] info:     zh:ember: [STACK STATUS] Network up.
[2024-05-11 17:55:55] info:     zh:ember: [INIT TC] NCP network does not match config. Leaving network...
[2024-05-11 17:55:56] info:     zh:ember: [STACK STATUS] Network down.
[2024-05-11 17:55:56] info:     zh:ember: [INIT TC] Config does not match backup.
[2024-05-11 17:55:56] info:     zh:ember: [INIT TC] Forming from config.
[2024-05-11 17:55:56] info:     zh:ember: [INIT FORM] Forming new network with: {"panId":41561,"extendedPanId":[230,39,242,190,207,166,187,144],"radioTxPower":5,"radioChannel":11,"joinMethod":0,"nwkManagerId":0,"nwkUpdateId":0,"channels":134215680}
[2024-05-11 17:55:56] info:     zh:ember: [STACK STATUS] Network up.
[2024-05-11 17:55:56] info:     zh:ember: [INIT FORM] New network formed!
[2024-05-11 17:55:56] info:     zh:ember: [CONCENTRATOR] Started source route discovery. 1247ms until next broadcast.
[2024-05-11 17:55:56] info:     zh:controller: Wrote coordinator backup to '/app/data/coordinator_backup.json'
[2024-05-11 17:55:56] info:     z2m: zigbee-herdsman started (reset)
[2024-05-11 17:55:56] info:     z2m: Coordinator firmware version: '{"meta":{"build":0,"ezsp":13,"major":7,"minor":4,"patch":1,"revision":"7.4.1 [GA]","special":0,"type":170},"type":"EmberZNet"}'
[2024-05-11 17:55:56] info:     z2m: Currently 0 devices are joined:
[2024-05-11 17:55:56] info:     z2m: Zigbee: disabling joining new devices.
[2024-05-11 17:55:56] info:     z2m: Connecting to MQTT server at mqtt://192.168.0.10
[2024-05-11 17:55:56] info:     z2m: Connected to MQTT server
[2024-05-11 17:55:56] info:     z2m: Started frontend on port 8080
[2024-05-11 17:55:56] info:     z2m: Zigbee2MQTT started!
[2024-05-11 17:55:57] error:    zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":163} messageTag=255]
[2024-05-11 17:55:57] error:    zh:ember: Delivery of BROADCAST failed for "65532" [apsFrame={"profileId":0,"clusterId":54,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":164} messageTag=1]
[2024-05-11 17:56:12] info:     z2m: Zigbee: allowing new devices to join.
[2024-05-11 17:56:12] info:     zh:ember: [STACK STATUS] Network opened.
[2024-05-11 17:56:13] error:    zh:ember: Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":166} messageTag=2]
[2024-05-11 17:56:13] error:    zh:ember: Delivery of BROADCAST failed for "65532" [apsFrame={"profileId":0,"clusterId":54,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":165} messageTag=255]

This is the z2m configuration:

homeassistant: true
permit_join: false
frontend: true
mqtt:
  base_topic: zigbee2mqtt
  server: mqtt://192.168.0.10
  user: homeassistant
  password: XXXXXXX
serial:
  port: tcp://192.168.0.11:6638
  baudrate: 115200
  adapter: ember
  rtscts: false
advanced:
  network_key: GENERATE
  pan_id: GENERATE
  ext_pan_id: GENERATE
  homeassistant_legacy_entity_attributes: false
  legacy_api: false
  legacy_availability_payload: false
device_options:
  legacy: false

I think backup from other coordinator has broken something, I've the backup json from it's original state.. how I can fully erase the adapter and start from scratch?

Thanks in advance!

wastez commented 5 days ago

Did you also override the ieee address of the adapter?

Without this it will not work.

Edit: If you want to earse everything you have to clear everything in z2m. (Config files, db) And also the adapter need a nvm3 reset, there is a special firmware file out there for such cases. xsp1989 had a nvm3 init file on his GitHub for such cases.

stich86 commented 5 days ago

Did you also override the ieee address of the adapter?

Without this it will not work.

Looks like the overwrite doesn't work on SiLabs adapter, IEEE address is still the original one (so migration not possible at current time)

wastez commented 5 days ago

@stich86 As far as i know the silabs universal firmware tool can override the ieee address, it has a option for it.

Nerivec commented 5 days ago

@stich86 Try updating the core firmware on your slzb-06m. There should be a new one (2.2.0) available.

stich86 commented 5 days ago

@stich86

As far as i know the silabs universal firmware tool can override the ieee address, it has a option for it.

Can you link that tool? I've used zigpy and the ezsp restore doesn't overwrite IEEE..

Thanks

alainsch commented 5 days ago

2.2.0 is still a dev firmware…

Nerivec commented 5 days ago

2.2.0 is still a dev firmware…

Ah, I was just relaying information. I've been told 2.2.0 fixes the state where several configs can't be set on startup. That state results in various instabilities thereafter.

stich86 commented 4 days ago

@stich86 As far as i know the silabs universal firmware tool can override the ieee address, it has a option for it.

So i've tried SiLab flash, but gives me this error when I try to rewrite IEEE:

universal-silabs-flasher --device /dev/cu.SLAB_USBtoUART write-ieee --ieee eXXXXXXXXX
2024-05-12 18:53:02.694 lynxs-MBP.local universal_silabs_flasher.flasher INFO Probing ApplicationType.GECKO_BOOTLOADER at 115200 baud
2024-05-12 18:53:03.793 lynxs-MBP.local universal_silabs_flasher.flasher INFO Detected bootloader version '1.A.3' (1.3)
2024-05-12 18:53:03.794 lynxs-MBP.local universal_silabs_flasher.flasher INFO Detected ApplicationType.GECKO_BOOTLOADER, version '1.A.3' (1.3) at 115200 baudrate (bootloader baudrate 115200)
Error: Device is not running EmberZNet: ApplicationType.GECKO_BOOTLOADER

Internal FW is ncp-uart-hw-v7.4.1.0-slzb-06m-115200.gbl

OK looks like it should not be in bootloader mode, anyway when put in normal mode still gives error:

universal-silabs-flasher --device /dev/cu.SLAB_USBtoUART write-ieee --ieee eXXX
2024-05-12 18:56:57.083 lynxs-MBP.local universal_silabs_flasher.flasher INFO Probing ApplicationType.GECKO_BOOTLOADER at 115200 baud
2024-05-12 18:56:59.177 lynxs-MBP.local universal_silabs_flasher.flasher INFO Probing ApplicationType.CPC at 460800 baud
2024-05-12 18:57:03.599 lynxs-MBP.local universal_silabs_flasher.flasher INFO Probing ApplicationType.CPC at 115200 baud
2024-05-12 18:57:08.010 lynxs-MBP.local universal_silabs_flasher.flasher INFO Probing ApplicationType.CPC at 230400 baud
2024-05-12 18:57:12.415 lynxs-MBP.local universal_silabs_flasher.flasher INFO Probing ApplicationType.EZSP at 115200 baud
2024-05-12 18:57:13.711 lynxs-MBP.local universal_silabs_flasher.flasher INFO Detected ApplicationType.EZSP, version '7.4.1.0 build 0' (7.4.1.0.0) at 115200 baudrate (bootloader baudrate None)
2024-05-12 18:57:14.876 lynxs-MBP.local universal_silabs_flasher.flasher INFO Current device IEEE: 80XXXXXXXXXX
Traceback (most recent call last):
  File "/opt/homebrew/bin/universal-silabs-flasher", line 8, in <module>
    sys.exit(main())
             ^^^^^^
  File "/opt/homebrew/lib/python3.11/site-packages/click/core.py", line 1157, in __call__
    return self.main(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/lib/python3.11/site-packages/click/core.py", line 1078, in main
    rv = self.invoke(ctx)
         ^^^^^^^^^^^^^^^^
  File "/opt/homebrew/lib/python3.11/site-packages/click/core.py", line 1688, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
                           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/lib/python3.11/site-packages/click/core.py", line 1434, in invoke
    return ctx.invoke(self.callback, **ctx.params)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/lib/python3.11/site-packages/click/core.py", line 783, in invoke
    return __callback(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/lib/python3.11/site-packages/click/decorators.py", line 33, in new_func
    return f(get_current_context(), *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/lib/python3.11/site-packages/universal_silabs_flasher/flash.py", line 40, in inner
    return asyncio.run(f(*args, **kwargs))
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/Cellar/python@3.11/3.11.6/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/runners.py", line 190, in run
    return runner.run(main)
           ^^^^^^^^^^^^^^^^
  File "/opt/homebrew/Cellar/python@3.11/3.11.6/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/runners.py", line 118, in run
    return self._loop.run_until_complete(task)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/Cellar/python@3.11/3.11.6/Frameworks/Python.framework/Versions/3.11/lib/python3.11/asyncio/base_events.py", line 653, in run_until_complete
    return future.result()
           ^^^^^^^^^^^^^^^
  File "/opt/homebrew/lib/python3.11/site-packages/universal_silabs_flasher/flash.py", line 258, in write_ieee
    await ctx.obj["flasher"].write_emberznet_eui64(new_eui64)
  File "/opt/homebrew/lib/python3.11/site-packages/universal_silabs_flasher/flasher.py", line 326, in write_emberznet_eui64
    if not await ezsp.can_write_custom_eui64():
                 ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/lib/python3.11/site-packages/bellows/ezsp/__init__.py", line 300, in __getattr__
    return getattr(self._protocol, name)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/opt/homebrew/lib/python3.11/site-packages/bellows/ezsp/protocol.py", line 144, in __getattr__
    raise AttributeError(f"{name} not found in COMMANDS")
AttributeError: can_write_custom_eui64 not found in COMMANDS
stich86 commented 4 days ago

i'm giving up on backup&restore, old stick on FW 6.1 has attribute can_write_custom_eui64 set to false, i've tried to move all diff from Dongle-E to SLZB-06M (also IEEE address), but when swapped the coordinator I got a lot of ROUTE_ERROR_ADDRESS_CONFLICT

So i'll try in the next days to start from scartch and move one-by-one all devices to the new coordinator :(

Ltek commented 3 days ago

first time seeing error while trying to add an Osram LED strip https://www.zigbee2mqtt.io/devices/4052899926110.html

Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":66} messageTag=55]

I've added several Bosch motion sensors and other sensors without this error, even yesterday. This is the first light I've ever tried (these are the only zigbee lights I have)

Sonoff Dongle-E w/ FW 7.4.3 and Z2M 1.73

andregoncalvespires commented 1 day ago

2.2.0 ainda é um firmware de desenvolvimento…

Hi. I'm using 2.2.0 version with 20240510 zigbee fw and ember. It's working very well for me. I have 86 devices and all are conecteds and responding queckly.

Nerivec commented 1 day ago

Closing this one in favor of https://github.com/Koenkk/zigbee2mqtt/issues/22453 to avoid repeating progress on this. Please see my last message there for those still having the issue.