zigbee2mqtt icon indicating copy to clipboard operation
zigbee2mqtt copied to clipboard

Published 20 hours ago • verified publisher icon Koenkk

1.35.0 crashing after upgrade.

Open djrm05 opened this issue 1 year ago • 4 comments

What happened?

Unable to start zigbee2mqtt after upgrade the image to latest (1.35.0). I see the following error in the log. Changing the image to 1.34.0, app start correctly without issues.``` TypeError: Cannot read properties of undefined (reading 'light_onoff_brightness') at Object. (/app/lib/extension/publish.ts:20:18) at Module._compile (node:internal/modules/cjs/loader:1256:14) at Object.Module._extensions..js (node:internal/modules/cjs/loader:1310:10) at Module.load (node:internal/modules/cjs/loader:1119:32) at Function.Module._load (node:internal/modules/cjs/loader:960:12) at Module.require (node:internal/modules/cjs/loader:1143:19) at require (node:internal/modules/cjs/helpers:119:18) at Object. (/app/lib/controller.ts:14:1) at Module._compile (node:internal/modules/cjs/loader:1256:14) at Object.Module._extensions..js (node:internal/modules/cjs/loader:1310:10)


### What did you expect to happen?

_No response_

### How to reproduce it (minimal and precise)

_No response_

### Zigbee2MQTT version

1.35.0

### Adapter firmware version

6.7.10.0 build 423

### Adapter

EZSP v8

### Debug log

_No response_

djrm05 avatar Jan 02 '24 13:01 djrm05

I have the same issue. 1.34 works fine, 1.35 doesn't start.

I get these logs:

info  2024-01-02 16:50:22: Logging to console and directory: '/app/data/log/2024-01-02.16-50-22' filename: log.txt
info  2024-01-02 16:50:22: Starting Zigbee2MQTT version 1.35.0 (commit #b5a90e9)
info  2024-01-02 16:50:22: Starting zigbee-herdsman (0.30.0)
info  2024-01-02 16:50:52: Accepting joining not in blocklist device '0xa4c138f24689e023'
info  2024-01-02 16:50:52: Accepting joining not in blocklist device '0xa4c138f24689e023'
error 2024-01-02 16:50:53: Failed to start zigbee
error 2024-01-02 16:50:53: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
error 2024-01-02 16:50:53: Exiting...
error 2024-01-02 16:50:53: Error: Read 0x0017880108d038e1/11 lightingColorCtrl(["colorCapabilities"], {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufact>    at ZStackAdapter.sendZclFrameToEndpointInternal (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/adapter/zStackAdapter.ts:415:23)
    at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)

TheHawk1337 avatar Jan 02 '24 16:01 TheHawk1337

@djrm05 how are you running z2m?

@TheHawk1337 could you provide the debug log?

See this on how to enable debug logging.

Koenkk avatar Jan 02 '24 21:01 Koenkk

@Koenkk docker managed through portainer

djrm05 avatar Jan 02 '24 22:01 djrm05

@Koenkk hope this helps. let me know if I can do something else

1.35.0:

Using '/app/data' as data directory
Zigbee2MQTT:debug 2024-01-03 00:26:28: Loaded state from file /app/data/state.json
Zigbee2MQTT:info  2024-01-03 00:26:28: Logging to console and directory: '/app/data/log/2024-01-03.00-26-28' filename: log.txt
Zigbee2MQTT:debug 2024-01-03 00:26:28: Removing old log directory '/app/data/log/2024-01-02.16-50-22'
Zigbee2MQTT:info  2024-01-03 00:26:28: Starting Zigbee2MQTT version 1.35.0 (commit #b5a90e9)
Zigbee2MQTT:info  2024-01-03 00:26:28: Starting zigbee-herdsman (0.30.0)
Zigbee2MQTT:debug 2024-01-03 00:26:28: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backupPath":"/app/data/coordinator_backup.json","databaseBackupPath":"/app/data/database.db.backup","databasePath":"/app/data/database.db","network":{"channelList":[11],"extendedPanID":[221,221,221,221,221,221,221,221],"networkKey":"HIDDEN","panID":6755},"serialPort":{"path":"/dev/ttyUSB0"}}'
Zigbee2MQTT:error 2024-01-03 00:27:00: Failed to start zigbee
Zigbee2MQTT:error 2024-01-03 00:27:00: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
Zigbee2MQTT:error 2024-01-03 00:27:00: Exiting...
Zigbee2MQTT:error 2024-01-03 00:27:00: Error: Read 0x0017880108d038e1/11 lightingColorCtrl(["colorCapabilities"], {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Data request failed with error: 'No network route' (205))
    at ZStackAdapter.sendZclFrameToEndpointInternal (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/adapter/zStackAdapter.ts:415:23)
    at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)

How it looks for 1.34.0:

Using '/app/data' as data directory
Zigbee2MQTT:debug 2024-01-03 00:27:42: Loaded state from file /app/data/state.json
Zigbee2MQTT:info  2024-01-03 00:27:42: Logging to console and directory: '/app/data/log/2024-01-03.00-27-42' filename: log.txt
Zigbee2MQTT:debug 2024-01-03 00:27:42: Removing old log directory '/app/data/log/2024-01-02.16-59-38'
Zigbee2MQTT:info  2024-01-03 00:27:42: Starting Zigbee2MQTT version 1.34.0 (commit #aae7312)
Zigbee2MQTT:info  2024-01-03 00:27:42: Starting zigbee-herdsman (0.25.0)
Zigbee2MQTT:debug 2024-01-03 00:27:42: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backupPath":"/app/data/coordinator_backup.json","databaseBackupPath":"/app/data/database.db.backup","databasePath":"/app/data/database.db","network":{"channelList":[11],"extendedPanID":[221,221,221,221,221,221,221,221],"networkKey":"HIDDEN","panID":6755},"serialPort":{"path":"/dev/ttyUSB0"}}'
Zigbee2MQTT:info  2024-01-03 00:27:53: zigbee-herdsman started (resumed)
Zigbee2MQTT:info  2024-01-03 00:27:53: Coordinator firmware version: '{"meta":{"maintrel":1,"majorrel":2,"minorrel":7,"product":1,"revision":20201026,"transportrev":2},"type":"zStack3x0"}'
Zigbee2MQTT:debug 2024-01-03 00:27:53: Zigbee network parameters: {"channel":11,"extendedPanID":"0xdddddddddddddddd","panID":6755}
Zigbee2MQTT:info  2024-01-03 00:27:53: Currently 49 devices are joined:
...... all of my devices here etc

TheHawk1337 avatar Jan 02 '24 23:01 TheHawk1337

@djrm05 are you overriding zigbee-herdsman-converters through a volume somehow?

@TheHawk1337 pushed a possible fix, please check with the latest-dev branch.

Changes will be available in the dev branch in a few hours from now.

Koenkk avatar Jan 03 '24 08:01 Koenkk

@Koenkk ok nice, will test asap (later tonight or tomorrow morning)!

TheHawk1337 avatar Jan 03 '24 09:01 TheHawk1337

@Koenkk I mapped the converters folder to a volume few weeks back in portainer, but then I removed the volume and thought this was OK. However after your comment, I just recreated the container and it started succesfully, so obviously something unexpected happened when I created and removed the volume for the previous container.

So thanks! for me this was fixed

djrm05 avatar Jan 03 '24 09:01 djrm05

@Koenkk No difference I think:


Using '/app/data' as data directory

Zigbee2MQTT:debug 2024-01-03 17:10:43: Loaded state from file /app/data/state.json

Zigbee2MQTT:info  2024-01-03 17:10:43: Logging to console and directory: '/app/data/log/2024-01-03.17-10-43' filename: log.txt

Zigbee2MQTT:debug 2024-01-03 17:10:43: Removing old log directory '/app/data/log/2024-01-02.17-04-29'

Zigbee2MQTT:info  2024-01-03 17:10:43: Starting Zigbee2MQTT version 1.35.0-dev (commit #e9aee4c)

Zigbee2MQTT:info  2024-01-03 17:10:43: Starting zigbee-herdsman (0.30.0)

Zigbee2MQTT:debug 2024-01-03 17:10:43: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backupPath":"/app/data/coordinator_backup.json","databaseBackupPath":"/app/data/database.db.backup","databasePath":"/app/data/database.db","network":{"channelList":[11],"extendedPanID":[221,221,221,221,221,221,221,221],"networkKey":"HIDDEN","panID":6755},"serialPort":{"path":"/dev/ttyUSB0"}}'

Zigbee2MQTT:error 2024-01-03 17:11:14: Failed to start zigbee

Zigbee2MQTT:error 2024-01-03 17:11:14: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions

Zigbee2MQTT:error 2024-01-03 17:11:14: Exiting...

Zigbee2MQTT:error 2024-01-03 17:11:14: Error: Read 0x0017880108d038e1/11 lightingColorCtrl(["colorCapabilities"], {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Data request failed with error: 'No network route' (205))

    at ZStackAdapter.sendZclFrameToEndpointInternal (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/adapter/zStackAdapter.ts:415:23)

    at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)

However, I don't think you should spend too much time on this, it appears I had some corruption on my system (portainer also had some issues) which might explain why zigbee2mqtt behaves like it does (or not, you probably know best).

TheHawk1337 avatar Jan 03 '24 16:01 TheHawk1337

@TheHawk1337 could you provide the herdsman debug log?

See this on how to enable the herdsman debug logging. Note that this is only logged to STDOUT and not to log files.

Koenkk avatar Jan 03 '24 19:01 Koenkk

@Koenkk See the attachments, bit too long to paste here. log_1_35_0.txt log_latest_dev.txt log_1_34_0.txt

Can move this to DM if you'd prefer, not sure if this clutters the thread here. Inexperienced at this, just want to help out :)

TheHawk1337 avatar Jan 04 '24 00:01 TheHawk1337

I found the issue! Fixed it

Changes will be available in the dev branch in a few hours from now.

Koenkk avatar Jan 04 '24 14:01 Koenkk

@Koenkk it still fails to start, see log:

log_latest_dev_bugfix.txt

Is it just this device being a pain: 0x0017880108d038e1 ?

Not sure where it comes from, some unsupported philips router? I'm confused. Can try deleting it (or leaving it in if you want to debug).

TheHawk1337 avatar Jan 05 '24 10:01 TheHawk1337

You are not running the latest dev branch, make sure to update to the latest.

Koenkk avatar Jan 05 '24 12:01 Koenkk

@Koenkk Sorry, that indeed was the case, didn't add the checkmark at pull image in portainer. Works flawlessly now!

TheHawk1337 avatar Jan 06 '24 01:01 TheHawk1337

@Koenkk Same issue here.

work fine with 1-33-1:

debug 2024-01-07 16:57:22: Loaded state from file /app/data/state.json
info  2024-01-07 16:57:22: Logging to console and directory: '/app/data/log/2024-01-07.16-57-22' filename: log.txt
debug 2024-01-07 16:57:22: Removing old log directory '/app/data/log/2024-01-07.13-07-16'
info  2024-01-07 16:57:22: Starting Zigbee2MQTT version 1.33.2 (commit #9996c93)
info  2024-01-07 16:57:22: Starting zigbee-herdsman (0.21.0)
debug 2024-01-07 16:57:22: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backupPath":"/app/data/coordinator_backup.json","databaseBackupPath":"/app/data/database.db.backup","databasePath":"/app/data/database.db","network":{"channelList":[11],"extendedPanID":[189,194,134,52,64,247,58,30],"networkKey":"HIDDEN","panID":30606},"serialPort":{"adapter":"ezsp","path":"/dev/ttyACM0"}}'
info  2024-01-07 16:57:28: zigbee-herdsman started (resumed)
info  2024-01-07 16:57:28: Coordinator firmware version: '{"meta":{"maintrel":"3 ","majorrel":"6","minorrel":"10","product":8,"revision":"6.10.3.0 build 297"},"type":"EZSP v8"}'
debug 2024-01-07 16:57:28: Zigbee network parameters: {"channel":11,"extendedPanID":189,"panID":30606}
info  2024-01-07 16:57:28: Currently 5 devices are joined:
info  2024-01-07 16:57:28: Contact Porte (0x00124b00292c5f3a): SNZB-04 - SONOFF Contact sensor (EndDevice)
info  2024-01-07 16:57:28: Lumiere Porche (0x9035eafffe0febda): ZBMINIL2 - SONOFF Zigbee smart switch (no neutral) (EndDevice)
info  2024-01-07 16:57:28: Temperature1 (0x3c2ef5fffebc2c6d): SNZB-02D - SONOFF Temperature and humidity sensor with screen (EndDevice)
info  2024-01-07 16:57:28: Temperature2 (0x3c2ef5fffeb9ae2c): SNZB-02D - SONOFF Temperature and humidity sensor with screen (EndDevice)
info  2024-01-07 16:57:28: 0x0c4314fffe086b50 (0x0c4314fffe086b50): E1603/E1702/E1708 - IKEA TRADFRI control outlet (Router)
warn  2024-01-07 16:57:28: `permit_join` set to  `true` in configuration.yaml.
warn  2024-01-07 16:57:28: Allowing new devices to join.
warn  2024-01-07 16:57:28: Set `permit_join` to `false` once you joined all devices.
info  2024-01-07 16:57:28: Zigbee: allowing new devices to join.
info  2024-01-07 16:57:28: Connecting to MQTT server at mqtt://172.17.0.1:1883
debug 2024-01-07 16:57:28: Using MQTT anonymous login
info  2024-01-07 16:57:28: Connected to MQTT server
info  2024-01-07 16:57:28: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload '{"state":"online"}'
info  2024-01-07 16:57:28: Started frontend on port 0.0.0.0:8080
info  2024-01-07 16:57:28: MQTT publish: topic 'zigbee2mqtt/Contact Porte', payload '{"battery":99,"battery_low":false,"contact":true,"linkquality":176,"tamper":false,"voltage":2900}'
info  2024-01-07 16:57:28: MQTT publish: topic 'zigbee2mqtt/Lumiere Porche', payload '{"linkquality":104,"state":"OFF","update":{"installed_version":4110,"latest_version":4110,"state":"idle"}}'
info  2024-01-07 16:57:28: MQTT publish: topic 'zigbee2mqtt/Temperature1', payload '{"battery":100,"humidity":51.5,"linkquality":172,"temperature":18}'
info  2024-01-07 16:57:28: MQTT publish: topic 'zigbee2mqtt/Temperature2', payload '{"battery":100,"humidity":59.4,"linkquality":80,"temperature":19.4}'
info  2024-01-07 16:57:28: MQTT publish: topic 'zigbee2mqtt/0x0c4314fffe086b50', payload '{"linkquality":172,"state":"OFF","update":{"installed_version":587765297,"latest_version":587765297,"state":"idle"}}'
info  2024-01-07 16:57:28: Zigbee2MQTT started!
debug 2024-01-07 16:57:44: Saving state to file /app/data/state.json
info  2024-01-07 16:57:44: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload '{"state":"offline"}'
info  2024-01-07 16:57:44: Disconnecting from MQTT server
info  2024-01-07 16:57:44: Stopping zigbee-herdsman...
info  2024-01-07 16:57:44: Stopped zigbee-herdsman
info  2024-01-07 16:57:44: Stopped Zigbee2MQTT

But don't start with 1-34 or 1-35:

debug 2024-01-07 17:00:50: Loaded state from file /app/data/state.json
info  2024-01-07 17:00:50: Logging to console and directory: '/app/data/log/2024-01-07.17-00-50' filename: log.txt
info  2024-01-07 17:00:50: Starting Zigbee2MQTT version 1.35.1-dev (commit #ef84ff8)
info  2024-01-07 17:00:50: Starting zigbee-herdsman (0.31.0)
debug 2024-01-07 17:00:50: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backupPath":"/app/data/coordinator_backup.json","databaseBackupPath":"/app/data/database.db.backup","databasePath":"/app/data/database.db","network":{"channelList":[11],"extendedPanID":[189,194,134,52,64,247,58,30],"networkKey":"HIDDEN","panID":30606},"serialPort":{"adapter":"ezsp","path":"/dev/ttyACM0"}}'
error 2024-01-07 17:01:10: Error while starting zigbee-herdsman
error 2024-01-07 17:01:10: Failed to start zigbee
error 2024-01-07 17:01:10: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
error 2024-01-07 17:01:10: Exiting...
error 2024-01-07 17:01:10: Error: Failure to connect
    at Ezsp.connect (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:279:19)
    at Driver.startup (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:139:9)
    at EZSPAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:172:16)
    at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:132:29)
    at Zigbee.start (/app/lib/zigbee.ts:60:27)
    at Controller.start (/app/lib/controller.ts:98:27)
    at start (/app/index.js:107:5)

Alexisdelyon avatar Jan 07 '24 17:01 Alexisdelyon

Could you provide the herdsman debug log of this?

See this on how to enable the herdsman debug logging. Note that this is only logged to STDOUT and not to log files.

Koenkk avatar Jan 08 '24 18:01 Koenkk

Could you provide the herdsman debug log of this?

See this on how to enable the herdsman debug logging. Note that this is only logged to STDOUT and not to log files.

Hi Koenkk, Thank you for your help. I understood where the error was coming from: I didn't set the privileges high enough for the container Docker. All is working fine. Thank you very much.

Alexisdelyon avatar Jan 08 '24 20:01 Alexisdelyon