zigbee2mqtt Trouble upgrading Home Assistant Zigbee2MQTT add-on v1.35.3-1 to 1.40.1-1

What happened?

Trying to upgrade Home Assistant Zigbee2MQTT add-on v1.35.3-1 to 1.40.1-1. Upgrade seems to go well, but z2m never seems to get ready:

[09:55:23] INFO: Preparing to start... [09:55:23] INFO: Socat not enabled [09:55:24] INFO: Starting Zigbee2MQTT... Starting Zigbee2MQTT without watchdog. [2024-09-10 09:55:25] info: z2m: Logging to console, file (filename: log.log) [2024-09-10 09:55:25] info: z2m: Starting Zigbee2MQTT version 1.40.1 (commit #unknown) [2024-09-10 09:55:25] info: z2m: Starting zigbee-herdsman (0.57.3) [2024-09-10 09:55:26] info: zh:zstack:znp: Opening SerialPort with {"path":"/dev/serial/by-id/usb-Silicon_Labs_Sonoff_Zigbee_3.0_USB_Dongle_Plus_0001-if00-port0","baudRate":115200,"rtscts":false,"autoOpen":false} [2024-09-10 09:55:26] info: zh:zstack:znp: Serialport opened

...and there it stops. WebUI is not accessible (502 bad gateway).

After trying to restore v1.35.3-1 it fails to start:

[09:59:14] INFO: Preparing to start... [09:59:14] INFO: Socat not enabled [09:59:14] INFO: Starting Zigbee2MQTT... Zigbee2MQTT:info 2024-09-10 09:59:16: Logging to console and directory: '/config/zigbee2mqtt/log/2024-09-10.09-59-16' filename: log.txt Zigbee2MQTT:info 2024-09-10 09:59:16: Starting Zigbee2MQTT version 1.35.3 (commit #unknown) Zigbee2MQTT:info 2024-09-10 09:59:16: Starting zigbee-herdsman (0.33.8) Zigbee2MQTT:error 2024-09-10 09:59:16: Error while starting zigbee-herdsman Zigbee2MQTT:error 2024-09-10 09:59:16: Failed to start zigbee Zigbee2MQTT:error 2024-09-10 09:59:16: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions Zigbee2MQTT:error 2024-09-10 09:59:16: Exiting... Zigbee2MQTT:error 2024-09-10 09:59:16: RangeError: Attempt to access memory outside buffer bounds at new NodeError (node:internal/errors:405:5) at boundsError (node:internal/buffer:86:11) at Buffer.readUInt16BE (node:internal/buffer:334:5) at /app/node_modules/zigbee-herdsman/src/utils/backup.ts:102:89 at Array.map () at Object.fromUnifiedBackup (/app/node_modules/zigbee-herdsman/src/utils/backup.ts:101:33) at AdapterBackup.getStoredBackup (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/adapter/adapter-backup.ts:50:32) at ZnpAdapterManager.determineStrategy (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/adapter/manager.ts:134:24) at ZnpAdapterManager.start (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/adapter/manager.ts:63:26) at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:132:29)

Home Assistant info:

Core 2024.9.1 Supervisor 2024.08.0 Operating System 13.1 Frontend 20240906.0

What did you expect to happen?

Successful upgrade.

How to reproduce it (minimal and precise)

Restore complete HASS with z2m 1.35.3-1. Upgrade z2m to 1.40.1-1.

Zigbee2MQTT version

1.35.3-1

Adapter firmware version

20220219

Adapter

Sonoff Dongle P

Setup

Home Assistant Add-on, x86-64

Debug log

No response

Sep 10 '24 08:09 mk1blacklimited

Could you try to upgrade and before starting rename coordinator_backup.json to coordinator_backup.json.old in the z2m data folder?

Sep 10 '24 12:09 Koenkk

Done, same problem unfortunately, log:

[14:58:48] INFO: Preparing to start... [14:58:48] INFO: Socat not enabled [14:58:49] INFO: Starting Zigbee2MQTT... Starting Zigbee2MQTT without watchdog. [2024-09-10 14:58:50] info: z2m: Logging to console, file (filename: log.log) [2024-09-10 14:58:50] info: z2m: Starting Zigbee2MQTT version 1.40.1 (commit #unknown) [2024-09-10 14:58:50] info: z2m: Starting zigbee-herdsman (0.57.3) [2024-09-10 14:58:50] info: zh:zstack:znp: Opening SerialPort with {"path":"/dev/serial/by-id/usb-Silicon_Labs_Sonoff_Zigbee_3.0_USB_Dongle_Plus_0001-if00-port0","baudRate":115200,"rtscts":false,"autoOpen":false} [2024-09-10 14:58:50] info: zh:zstack:znp: Serialport opened

Sep 10 '24 13:09 mk1blacklimited

Could you provide the complete log? I don't see any error in there.

Sep 12 '24 18:09 Koenkk

Well, that’s just the thing, after it says «Serialport opened» there’s nothing in the log.

Sep 12 '24 19:09 mk1blacklimited

Is there a way to upgrade to a lesser version of the z2m addon in HA?

Sep 13 '24 12:09 mk1blacklimited

I think not, do you see anything in the debug log?

See this on how to enable debug logging.

Sep 13 '24 16:09 Koenkk

I can't see anything I can perceive as a clear error. Is it OK to attach the log file here (i.e. is there something I should remove from the file before posting it)?

Sep 19 '24 10:09 mk1blacklimited

@Koenkk - ping :)

Sep 26 '24 08:09 mk1blacklimited

Just tried 1.40.2-1, still the same problem. Really need help here. I have an older FW version in the stick (20220219), could that be the problem?

Oct 28 '24 13:10 mk1blacklimited

I have an older FW version in the stick (20220219), could that be the problem?

Try upgrading and see if it helps

Oct 28 '24 20:10 Koenkk

Right, upgraded to 20240710. z2m v1.35.3-1 worked fine after upgrading the firmware. Then I tried to upgrade z2m 1.40.2-1:

[09:30:12] INFO: Preparing to start... [09:30:12] INFO: Socat not enabled [09:30:12] INFO: Starting Zigbee2MQTT... Starting Zigbee2MQTT without watchdog. [2024-10-30 09:30:14] info: z2m: Logging to console, file (filename: log.log) [2024-10-30 09:30:14] info: z2m: Starting Zigbee2MQTT version 1.40.2 (commit #unknown) [2024-10-30 09:30:14] info: z2m: Starting zigbee-herdsman (2.1.3) [2024-10-30 09:30:14] error: zh:zstack:znp: Failed to determine if path is valid: 'Error: spawn udevadm ENOENT' [2024-10-30 09:30:14] info: zh:zstack:znp: Opening SerialPort with {"path":"/dev/serial/by-id/usb-Silicon_Labs_Sonoff_Zigbee_3.0_USB_Dongle_Plus_0001-if00-port0","baudRate":115200,"rtscts":false,"autoOpen":false} [2024-10-30 09:30:14] info: zh:zstack:znp: Serialport opened [2024-10-30 09:30:14] error: zh:zstack:znp: Error while parsing to ZpiObject 'TypeError: Cannot read properties of undefined (reading 'execute')'

Note the last line, haven't seen that before.

stopped z2m:

[2024-10-30 09:33:28] error: z2m: Not connected to MQTT server! [2024-10-30 09:33:28] error: z2m: Cannot send message: topic: 'zigbee2mqtthjemme/bridge/state', payload: '{"state":"offline"} [2024-10-30 09:33:28] info: z2m: Disconnecting from MQTT server [2024-10-30 09:33:28] info: z2m: Stopping zigbee-herdsman... [2024-10-30 09:33:36] info: zh:controller: Wrote coordinator backup to '/config/zigbee2mqtt/coordinator_backup.json' [2024-10-30 09:33:36] info: zh:zstack:znp: closing [2024-10-30 09:33:36] info: zh:zstack:znp: Port closed [2024-10-30 09:33:36] info: z2m: Stopped zigbee-herdsman [2024-10-30 09:33:36] info: z2m: Stopped Zigbee2MQTT

Set z2m not to start automatically after Home Assistant restart.

Restarted Home Assistant and started z2m:

[09:36:03] INFO: Preparing to start... [09:36:03] INFO: Socat not enabled [09:36:04] INFO: Starting Zigbee2MQTT... Starting Zigbee2MQTT without watchdog. [2024-10-30 09:36:05] info: z2m: Logging to console, file (filename: log.log) [2024-10-30 09:36:05] info: z2m: Starting Zigbee2MQTT version 1.40.2 (commit #unknown) [2024-10-30 09:36:05] info: z2m: Starting zigbee-herdsman (2.1.3) [2024-10-30 09:36:06] error: zh:zstack:znp: Failed to determine if path is valid: 'Error: spawn udevadm ENOENT' [2024-10-30 09:36:06] info: zh:zstack:znp: Opening SerialPort with {"path":"/dev/serial/by-id/usb-Silicon_Labs_Sonoff_Zigbee_3.0_USB_Dongle_Plus_0001-if00-port0","baudRate":115200,"rtscts":false,"autoOpen":false} [2024-10-30 09:36:06] info: zh:zstack:znp: Serialport opened

And then nothing. :(

This is the configuration: 2024-10-30 09_44_10-Clipboard

Oct 30 '24 08:10 mk1blacklimited

Could you activate the debug logging? You probably need to use the file explorer addon to edit the z2m configuration.yaml.

See this on how to enable debug logging.

Oct 31 '24 20:10 Koenkk

I've done that before, and then I asked: "Is it OK to attach the log file here (i.e. is there something I should remove from the file before posting it)?" which I failed to get a reply to. :) If it's OK to post here then I will ASAP. :)

Nov 01 '24 08:11 mk1blacklimited

Please post it here.

Nov 02 '24 19:11 Koenkk

OK, here it is. log.log

Nov 04 '24 07:11 mk1blacklimited

It seems it cannot connect to the MQTT broker:

[2024-09-19 12:45:23] error: 	z2m: Not connected to MQTT server!
[2024-09-19 12:45:23] error: 	z2m: Cannot send message: topic: 'zigbee2mqtthjemme/bridge/state', payload: '{"state":"offline"}
[2024-09-19 12:45:23] info: 	z2m: Disconnecting from MQTT server
[2024-09-19 12:45:23] info: 	z2m: Stopping zigbee-herdsman...

Try following step 5 of https://github.com/zigbee2mqtt/hassio-zigbee2mqtt/blob/master/README.md

Nov 05 '24 21:11 Koenkk

OK - updated z2m to 1.41.0-1. Then I got this in the log page:

Configured MQTT as such:

Still the same.

Turned on debug log:

[2024-11-07 09:28:16] info: z2m: Logging to console, file (filename: log.log) [2024-11-07 09:28:16] info: z2m: Starting Zigbee2MQTT version 1.41.0 (commit #unknown) [2024-11-07 09:28:16] info: z2m: Starting zigbee-herdsman (2.1.7) [2024-11-07 09:28:16] info: zh:zstack:znp: Opening SerialPort with {"path":"/dev/serial/by-id/usb-Silicon_Labs_Sonoff_Zigbee_3.0_USB_Dongle_Plus_0001-if00-port0","baudRate":115200,"rtscts":false,"autoOpen":false} [2024-11-07 09:28:16] info: zh:zstack:znp: Serialport opened [2024-11-07 09:28:47] error: z2m: Failed to call 'Frontend' 'stop' (TypeError: Cannot read properties of undefined (reading 'clients') at Frontend.stop (/app/lib/extension/frontend.ts:114:18) at Controller.callExtensions (/app/lib/controller.ts:399:17) at Controller.stop (/app/lib/controller.ts:265:9) at stop (/app/index.js:165:5) at process.handleQuit (/app/index.js:173:13)) [2024-11-07 09:28:47] error: z2m: Not connected to MQTT server! [2024-11-07 09:28:47] error: z2m: Cannot send message: topic: 'zigbee2mqtthjemme/bridge/state', payload: '{"state":"offline"} [2024-11-07 09:28:47] info: z2m: Disconnecting from MQTT server [2024-11-07 09:28:47] info: z2m: Stopping zigbee-herdsman... [2024-11-07 09:28:55] info: zh:controller: Wrote coordinator backup to '/config/zigbee2mqtt/coordinator_backup.json' [2024-11-07 09:28:55] info: zh:zstack:znp: closing [2024-11-07 09:28:55] info: zh:zstack:znp: Port closed [2024-11-07 09:28:55] info: z2m: Stopped zigbee-herdsman [2024-11-07 09:28:55] info: z2m: Stopped Zigbee2MQTT

MQTT server (addon in HomeAssistant) is definitly running, nothing else has trouble connecting to it.

Nov 07 '24 09:11 mk1blacklimited

It seems the error is a bit different now, could you provide the debug log again?

Nov 07 '24 19:11 Koenkk

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 7 days

Jan 07 '25 00:01 github-actions[bot]

Just to remove stale label. Issue not fixed yet, I haven't had time to research any more. Will continue soon.

Jan 09 '25 07:01 mk1blacklimited

Right, finally had the time to test some more. Upgrading from v1.35.3-1 to 2.1.0-1 this time. Still not working unfortunately, but here are a couple of debug logs.

45df7312_zigbee2mqtt_2025-02-04T07-47-37.427Z.log 45df7312_zigbee2mqtt_2025-02-04T07-53-33.935Z.log

Feb 04 '25 07:02 mk1blacklimited

To test, uninstalled z2m addon, renamed the zigbee2mqtt folder in /homeassistant and reinstalled the addon. Without configuring anything, just started it up and it started fine:

[08:59:28] INFO: Preparing to start... [08:59:28] INFO: Socat not enabled [08:59:28] INFO: Starting Zigbee2MQTT... Starting Zigbee2MQTT without watchdog. [2025-02-04 08:59:30] info: z2m: Logging to console, file (filename: log.log) [2025-02-04 08:59:30] info: z2m: Starting Zigbee2MQTT version 2.1.0 (commit #unknown) [2025-02-04 08:59:30] info: z2m: Starting zigbee-herdsman (3.2.5) [2025-02-04 08:59:30] info: zh:adapter:discovery: Matched adapter: {"path":"/dev/ttyUSB0","manufacturer":"Silicon Labs","serialNumber":"0001","pnpId":"usb-Silicon_Labs_Sonoff_Zigbee_3.0_USB_Dongle_Plus_0001-if00-port0","vendorId":"10c4","productId":"ea60"} => zstack: path=/dev/ttyUSB0, score=4 [2025-02-04 08:59:30] info: zh:zstack:znp: Opening SerialPort with {"path":"/dev/ttyUSB0","baudRate":115200,"rtscts":false,"autoOpen":false} [2025-02-04 08:59:30] info: zh:zstack:znp: Serialport opened [2025-02-04 08:59:46] info: zh:controller: Wrote coordinator backup to '/config/zigbee2mqtt/coordinator_backup.json' [2025-02-04 08:59:46] info: z2m: zigbee-herdsman started (reset) [2025-02-04 08:59:46] info: z2m: Coordinator firmware version: '{"meta":{"maintrel":1,"majorrel":2,"minorrel":7,"product":1,"revision":20240710,"transportrev":2},"type":"zStack3x0"}' [2025-02-04 08:59:46] info: z2m: Currently 0 devices are joined. [2025-02-04 08:59:46] info: z2m: Connecting to MQTT server at mqtt://core-mosquitto:1883 [2025-02-04 08:59:47] info: z2m: Connected to MQTT server [2025-02-04 08:59:47] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload '{"state":"online"}' [2025-02-04 08:59:47] info: z2m: Started frontend on port 8099

Feb 04 '25 08:02 mk1blacklimited

This indicates to me a problem with one (or more) of the configuration files, what do you think, @Koenkk ?

Feb 06 '25 07:02 mk1blacklimited

Tought I'd wrap up this topic as it is resolved. :)

I thought I should give a normal update another quick try before removing z2m and reinstalling. Upgrading from 1.35 to 2.1.3-1, and except for an addition of "adapter: zstack" in the config file, it started right up! Amazing, I guess @Koenkk has done some magic behind the scenes. :)

Mar 13 '25 11:03 mk1blacklimited

This issue is stale because it has been open 60 days with no activity. Remove stale label or comment or this will be closed in 7 days

May 13 '25 00:05 github-actions[bot]