zigbee2mqtt icon indicating copy to clipboard operation
zigbee2mqtt copied to clipboard

Published 20 hours ago • verified publisher icon Koenkk

Dongle-E 7.4.2 ember initial startup errors and broadcast error

Open supaeasy opened this issue 9 months ago • 33 comments

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

supaeasy avatar May 02 '24 09:05 supaeasy

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

alainsch avatar May 02 '24 14:05 alainsch

@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?

wastez avatar May 02 '24 18:05 wastez

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.

supaeasy avatar May 02 '24 18:05 supaeasy

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.

wastez avatar May 02 '24 19:05 wastez

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 😉

Nerivec avatar May 02 '24 21:05 Nerivec

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.

supaeasy avatar May 02 '24 21:05 supaeasy

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

diegocade1 avatar May 03 '24 13:05 diegocade1

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

Ciqsky avatar May 04 '24 21:05 Ciqsky

@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.

Nerivec avatar May 04 '24 21:05 Nerivec

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 avatar May 04 '24 22:05 Ciqsky

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

Ciqsky avatar May 04 '24 22:05 Ciqsky

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.

Nerivec avatar May 04 '24 22:05 Nerivec

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

Ciqsky avatar May 04 '24 22:05 Ciqsky

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

Ciqsky avatar May 04 '24 22:05 Ciqsky

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.

Nerivec avatar May 04 '24 23:05 Nerivec

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

remidebette avatar May 05 '24 08:05 remidebette

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!

Ciqsky avatar May 05 '24 11:05 Ciqsky

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.

Nerivec avatar May 05 '24 12:05 Nerivec

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

Ricc68 avatar May 06 '24 17:05 Ricc68

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  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:

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

XFNeo avatar May 08 '24 09:05 XFNeo 

[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.

LookInIs avatar May 10 '24 08:05 LookInIs

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.

Nerivec avatar May 10 '24 10:05 Nerivec

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!

stich86 avatar May 11 '24 18:05 stich86

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.

wastez avatar May 11 '24 18:05 wastez

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)

stich86 avatar May 11 '24 18:05 stich86

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

wastez avatar May 11 '24 18:05 wastez

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

Nerivec avatar May 11 '24 18:05 Nerivec

@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

stich86 avatar May 11 '24 18:05 stich86

2.2.0 is still a dev firmware…

alainsch avatar May 11 '24 18:05 alainsch

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.

Nerivec avatar May 11 '24 19:05 Nerivec