Z2M cannot start with SLZB-06M

[maciekdnd]

What happened?

I'm unable to start Z2M. I see only errors like here:

[2024-07-17 16:25:33] error: zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE.
[2024-07-17 16:25:33] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR
[2024-07-17 16:25:33] error: zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR.
[2024-07-17 16:25:33] error: zh:ember: !!! NCP FATAL ERROR reason=HOST_FATAL_ERROR. ATTEMPTING RESET... !!!
[2024-07-17 16:25:36] error: zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE.
[2024-07-17 16:25:36] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR
[2024-07-17 16:25:36] error: zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR.
[2024-07-17 16:25:36] error: zh:ember: !!! NCP FATAL ERROR reason=HOST_FATAL_ERROR. ATTEMPTING RESET... !!!
[2024-07-17 16:25:54] error: zh:ember: !!! NCP FATAL ERROR reason=ERROR_SERIAL_INIT. ATTEMPTING RESET... !!!
[2024-07-17 16:25:55] error: zh:ember: Failed to reset and init NCP. Error: Stack type 0 is not expected!
[2024-07-17 16:25:55] error: z2m: Adapter disconnected, stopping

Strangely enough, Z2M was running perfectly fine for few weeks. Right now I can say it's random. One time it can start without any problems, other time it fails like this.
I also tried to update to latest firmware (7.4.3) but I got same response.
I have two SLZB-06M in two separate networks (two LXC containers), both behave same.

Part of my config:
mqtt:
base_topic: z2m_1
server: mqtt://192.168.3.100:1883
user: mqtt_ha
password: ****
version: 5
keepalive: 60
reject_unauthorized: true
serial:
port: tcp://192.168.3.11:6638
baudrate: 115200
rtscts: false
adapter: ember

I tried to reset controllers by reset by web console, disconnecting them from POE, rebooting containers. Nothing works. During start both works (I see web ui for controllers).

What should I do to get it working?

What did you expect to happen?

Clean Z2M start without errors

How to reproduce it (minimal and precise)

run Z2M: cd /opt/zigbee2mqtt && npm start

Zigbee2MQTT version

1.38.0

Adapter firmware version

20240510

Adapter

SLZB-06M

Setup

Z2M in Proxmox LXC container

Debug log

No response

[maciekdnd]

I accidentally deleted coordinator_backup.json and now Z2M starts perfectly fine. Why?

[gravcyber]

Experienced the same problem right now, thanks to @maciekdnd discovery i could fix it instantly. I am on Zigbee2MQTT 1.39.0

[maciekdnd]

For some reason I'm unable to start Z2M today. Even when I rm coordinator_backup.yaml. Right now I have no idea what is going on. One time I have clean, perfect start and other I can't start even once. Can someone help?

[maciekdnd]

Another day, another finding. I can restart Z2M in LXC container using systemctl restart zigbee2mqtt.service. Looks like clean start and hope for near feature.

[andyblac]

I found that if you restart reboot HA, you also need to reboot your SLZB-06M as well.

[maciekdnd]

My routine after restarting or powering down for now is:

rm opt/zigbee2mqtt/data/coordinator_backup.json
systemctl restart zigbee2mqtt.service

When I configure watchdog, like this:

WatchdogSec=10s
Restart=always
RestartSec=10s

I have to delete coordinator_backup.json every time anyway. With the file present, Z2M is unable to boot in my configuration, in all 3 networks.

[itinfosec]

I have been having a similar issue with setting up Z2MQTT with an SLZB-06M and have been getting the following errors which haven't been overly useful in figuring out what is wrong.

[2024-07-30 05:15:00] error: zh:ember:uart:ash: Received frame with CRC error
[2024-07-30 05:15:00] error: zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-07-30 05:15:00] error: zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR
[2024-07-30 05:15:00] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-07-30 05:15:00] info: zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-07-30 05:15:00] info: zh:ember:uart:ash: ======== ASH starting ========
[2024-07-30 05:15:01] info: zh:ember:uart:ash: ======== ASH connected ========
[2024-07-30 05:15:01] info: zh:ember:uart:ash: ======== ASH started ========
[2024-07-30 05:15:01] info: zh:ember:ezsp: ======== EZSP started ========
[2024-07-30 05:15:02] warning: zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e]
[2024-07-30 05:15:02] error: zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE.
[2024-07-30 05:15:02] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR
[2024-07-30 05:15:02] error: zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR.
[2024-07-30 05:15:02] error: zh:ember: !!! NCP FATAL ERROR reason=HOST_FATAL_ERROR. ATTEMPTING RESET... !!!

[yeyeoke]

Same issue here, running in docker. When restarting the Zigbee2mqtt container, It fails to start. It's solved by restarting the container again, then everything comes back up without issue.

[andyblac]

I get similar on restarting HA OS

[13:41:48] INFO: Preparing to start...
[13:41:48] INFO: Socat not enabled
[13:41:49] INFO: Starting Zigbee2MQTT...
Starting Zigbee2MQTT without watchdog.
[2024-07-30 13:41:50] error: 	zh:ember:uart:ash: Received frame with CRC error
[2024-07-30 13:41:50] error: 	zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-07-30 13:41:50] error: 	zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR
[2024-07-30 13:41:50] error: 	zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-07-30 13:41:53] warning: 	zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e]
[2024-07-30 13:41:53] error: 	zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE.
[2024-07-30 13:41:53] error: 	zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR
[2024-07-30 13:41:53] error: 	zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR.
[2024-07-30 13:41:53] error: 	zh:ember: !!! NCP FATAL ERROR reason=HOST_FATAL_ERROR. ATTEMPTING RESET... !!!
[2024-07-30 13:42:50] error: 	zh:ember: !!! NCP FATAL ERROR reason=ERROR_SERIAL_INIT. ATTEMPTING RESET... !!!
[2024-07-30 13:42:54] error: 	z2m: Not connected to MQTT server!
[2024-07-30 13:42:54] error: 	z2m: Cannot send message: topic: 'zigbee2mqtt_slzb-06m/bridge/state', payload: '{"state":"offline"}

once I reboot the SLZB-06M Z2M starts normally.

[13:42:55] INFO: Preparing to start...
[13:42:55] INFO: Socat not enabled
[13:42:55] INFO: Starting Zigbee2MQTT...
Starting Zigbee2MQTT without watchdog.

[pepe59]

After updating Z2M 1.39.1-1, it can no longer run.
I reverted to Z2M 1.39.0-1 and it works as expected.
I am using Z2M addon in HA. SLZB-06M coordinator
Does anyone have the same problem, or how to make it work on the new version of Z2M 1.39.1-1?

[MilesTEG1]

After updating Z2M 1.39.1-1, it can no longer run. I reverted to Z2M 1.39.0-1 and it works as expected. I am using Z2M addon in HA. SLZB-06M coordinator Does anyone have the same problem, or how to make it work on the new version of Z2M 1.39.1-1?

For me, no problem with the 1.39.1-1 Z2M version.
I don't encounter the addon can't start after boot. But I'll have to verify this.

[GordonSmith-db]

I am using a SLZB-06 (not M) and just got this today on Z2M 1.39.1-1. Any ideas? I noticed this an hour later and found Z2M wasn't running. When I clicked "start", it started just fine.

[2024-08-06 20:11:09] info: 	zh:zstack:znp: Socket error
[2024-08-06 20:11:09] info: 	zh:zstack:znp: Port closed
[2024-08-06 20:11:09] info: 	zh:zstack:znp: closing
[2024-08-06 20:11:09] error: 	z2m: Adapter disconnected, stopping
[2024-08-06 20:11:09] info: 	z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload '{"state":"offline"}'
[2024-08-06 20:11:09] info: 	z2m: Disconnecting from MQTT server
[2024-08-06 20:11:09] info: 	z2m: Stopping zigbee-herdsman...
[2024-08-06 20:11:09] info: 	z2m: Stopped zigbee-herdsman
[2024-08-06 20:11:09] info: 	z2m: Stopped Zigbee2MQTT
[20:11:11] INFO: Preparing to start...
[20:11:12] INFO: Socat not enabled
[20:11:18] INFO: Starting Zigbee2MQTT...
Starting Zigbee2MQTT without watchdog.
[2024-08-06 20:11:28] info: 	z2m: Logging to console, file (filename: log.log)
[2024-08-06 20:11:28] info: 	z2m: Starting Zigbee2MQTT version 1.39.1 (commit #unknown)
[2024-08-06 20:11:28] info: 	z2m: Starting zigbee-herdsman (0.55.3)
[2024-08-06 20:11:28] info: 	zh:zstack:znp: Opening TCP socket with 192.168.68.83:6638
[2024-08-06 20:11:28] info: 	zh:zstack:znp: Socket error
[2024-08-06 20:11:28] error: 	z2m: Error while starting zigbee-herdsman
[2024-08-06 20:11:28] error: 	z2m: Failed to start zigbee
[2024-08-06 20:11:28] error: 	z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
[2024-08-06 20:11:28] error: 	z2m: Exiting...
[2024-08-06 20:11:29] error: 	z2m: Error: Error while opening socket
    at Socket.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/znp.ts:185:24)
    at Socket.emit (node:events:529:35)
    at emitErrorNT (node:internal/streams/destroy:151:8)
    at emitErrorCloseNT (node:internal/streams/destroy:116:3)
    at processTicksAndRejections (node:internal/process/task_queues:82:21)

/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:264
  var er = new ERR_STREAM_WRITE_AFTER_END();
           ^
Error: write after end
    at writeAfterEnd (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:264:12)
    at DerivedLogger.Writable.write (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:300:21)
    at DerivedLogger.log (/app/node_modules/winston/lib/winston/logger.js:231:12)
    at Logger.log (/app/lib/util/logger.ts:189:25)
    at Logger.info (/app/lib/util/logger.ts:202:14)
    at Znp.onPortClose (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/znp.ts:107:16)
    at Object.onceWrapper (node:events:632:26)
    at Socket.emit (node:events:517:28)
    at TCP.<anonymous> (node:net:350:12)
[21:32:40] INFO: Preparing to start...
[21:32:41] INFO: Socat not enabled
[21:32:47] INFO: Starting Zigbee2MQTT...
Starting Zigbee2MQTT without watchdog.
[2024-08-06 21:32:57] info: 	z2m: Logging to console, file (filename: log.log)
[2024-08-06 21:32:57] info: 	z2m: Starting Zigbee2MQTT version 1.39.1 (commit #unknown)
[2024-08-06 21:32:57] info: 	z2m: Starting zigbee-herdsman (0.55.3)
[2024-08-06 21:32:58] info: 	zh:zstack:znp: Opening TCP socket with 192.168.68.83:6638
[2024-08-06 21:32:58] info: 	zh:zstack:znp: Socket connected