search

zigbee2mqtt / hassio-zigbee2mqtt

Official Zigbee2MQTT Home Assistant add-on
https://www.zigbee2mqtt.io
Apache License 2.0
1.19k stars 435 forks source link

After update 1.35.2 to 1.35.3 ZigBee2MQTT Started and next 30 second Stopped #566

Closed asan84 closed 8 months ago

asan84 commented 9 months ago

Description of the issue

After update 1.35.2 to 1.35.3 ZigBee2MQTT Started and next 15-30 second Stopped :(((

In Log:

/app/node_modules/winston-transport/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-transport/node_modules/readable-stream/lib/_stream_writable.js:264:12) at File.Writable.write (/app/node_modules/winston-transport/node_modules/readable-stream/lib/_stream_writable.js:300:21) at DerivedLogger.ondata (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_readable.js:629:20) at DerivedLogger.emit (node:events:517:28) at DerivedLogger.Readable.read (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_readable.js:451:26) at flow (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_readable.js:858:34) at File.pipeOnDrainFunctionResult (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_readable.js:690:7) at File.emit (node:events:517:28) at onwriteDrain (/app/node_modules/winston-transport/node_modules/readable-stream/lib/_stream_writable.js:453:12) at afterWrite (/app/node_modules/winston-transport/node_modules/readable-stream/lib/_stream_writable.js:441:18)

How to downgrade or fix a this error?

Addon version

1.35.3

Platform

Home Assistant 2024.1.6 Supervisor 2024.01.1 Debian 12 OS Agent 1.6.0 Docker 25.0.3 Coordinator firmware version: 6.6.5.0 build 204, type: EZSP v7

Logs of the issue (if applicable)

No response

Maro20000 commented 9 months ago

remove and insert the USB coordinator, it helped me

asan84 commented 9 months ago

remove and insert the USB coordinator, it helped me

I tried it, completely disconnected the power, turned it on, the error did not go away.

How to go back to 1.35.2? I don't understand what the problem is with the new version.

tm8 commented 9 months ago

+1 The same here . How to go back to 1.35.2? Zigbee2MQTT-Version 1.35.3 commit: unknown Coordinator-Typ zStack3x0 Coordinator-Version 20230507 Coordinator IEEE Adresse 0x00124b002c3a6401 Frontend-Version 0.6.156 zigbee_herdsman_converters_version 18.28.3 zigbee_herdsman_version 0.33.8 Statistiken Gesamt 58 Nach Typ Router: 33 Endgerät: 25

Rookman2022 commented 9 months ago

I have the same problem in version 135.2-1 and also in 135.3-1 Coordinator-Typ: Skyconnect EZSP v12 Coordinator-Version 7.3.2.0 build 212 Router: 63 Endgerät: 30

tm8 commented 9 months ago

I tried to solve the problem by switching back to version 1.35.2-1 (backup of Home Assistant), but without success.

Rookman2022 commented 9 months ago

Only 135.1-1 works for me, all subsequent versions have the problem. The 135.1-1 runs without any problems.

gdesmott commented 9 months ago

Same problem here with 1.35.3-1 but I don't have much details in /config/logs:

[17:59:29] INFO: Preparing to start...
[17:59:31] INFO: Socat not enabled
[17:59:37] INFO: Starting Zigbee2MQTT...
Koenkk commented 9 months ago

@asan84 can you provide me your z2m configuration.yaml?

tm8 commented 9 months ago

@asan84 can you provide me your z2m configuration.yaml?

Hello Koenkk, here is my configuration.yaml. X = Secret :-)

homeassistant: true advanced: channel: 15 network_key:

tm8 commented 9 months ago

I have two Sonoff Dongles:

Zigbee2MQTT-Version 1.35.2 commit: unknown Coordinator-Typ zStack3x0 Coordinator-Version 20230507 Coordinator IEEE Adresse 0x00124b002c3a6401 Frontend-Version 0.6.152 Zigbee-herdsman-converters version 18.25.1 Zigbee-herdsman version 0.33.5

asan84 commented 9 months ago

@asan84 can you provide me your z2m configuration.yaml? I attached my config

configuration.zip

Koenkk commented 9 months ago

I think it's because of the log_syslog, can you remove it from your configuration.yaml and see if that fixes the problem?

tm8 commented 9 months ago

I think it's because of the log_syslog, can you remove it from your configuration.yaml and see if that fixes the prob

Hi Koenkk, thanks for the feedback. Unfortunately no change in behavior. The adapter restarts every 3-4 minutes for me. I am back to version 1.35.1, no problems there, the adapter runs stable.

PrzemsiMat commented 9 months ago

the same issue Current version: 1.35.3-1 ZB-GW04 USB

asan84 commented 9 months ago

I think it's because of the log_syslog, can you remove it from your configuration.yaml and see if that fixes the problem?

I didn't turn off the log_syslog. The service started automatically after stopping on the 10th attempt. It has loaded and hasn't stopped yet.

I don't understand what the problem is with the new version.

Koenkk commented 9 months ago

@asan84 can you SSH into your system, execute the following and see if the issue is fixed?

docker exec -it $(docker ps | grep zigbee2mqtt | cut -d" " -f 1) /bin/sh
apk add npm
npm install winston-transport@4.6.0
exit
docker restart $(docker ps | grep zigbee2mqtt | cut -d" " -f 1)

Make sure to not restart the addon via the HA interface, these changes will get lost.

asan84 commented 9 months ago

@asan84 can you SSH into your system, execute the following and see if the issue is fixed?

docker exec -it $(docker ps | grep zigbee2mqtt | cut -d" " -f 1) /bin/sh
apk add npm
npm install winston-transport@4.6.0
exit
docker restart $(docker ps | grep zigbee2mqtt | cut -d" " -f 1)

Make sure to not restart the addon via the HA interface, these changes will get lost.

It did not work, now the process is rebooting again.

The last time it gave an error and stopped: [22:38:47] INFO: Preparing to start... [22:38:52] INFO: Socat not enabled [22:39:09] INFO: Starting Zigbee2MQTT... Zigbee2MQTT:error 2024-02-18 22:40:10: Failed to read state of '0x588e81fffeb07c8a' after reconnect (Read 0x588e81fffeb07c8a/1 genOnOff(["onOff"], {"timeout":10000,"disableResponse":false, "disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (sendZclFrameToEndpointInternal error))

The process started stably after 5 minutes, after several falls.

But, process stopped again:

[22:41:52] INFO: Preparing to start... [22:41:57] INFO: Socat not enabled [22:42:14] INFO: Starting Zigbee2MQTT... Zigbee2MQTT:error 2024-02-18 22:48:19: Failed to configure '0x54ef44100087d7f0', attempt 1 (Error: Read 0x54ef44100087d7f0/1 genPowerCfg(["batteryVoltage"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Timeout - 30829 - 1 - 12 - 1 - 1 after 10000ms) at Object.start (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:63:23) at EZSPAdapter.sendZclFrameToEndpointInternal (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/adapter/ezspAdapter.ts:486:47) at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20) at Request.send (/app/node_modules/zigbee-herdsman/src/controller/helpers/request.ts:79:20) at Endpoint.read (/app/node_modules/zigbee-herdsman/src/controller/model/endpoint.ts:466:28) at configure (/app/node_modules/zigbee-herdsman-converters/src/devices/lumi.ts:1778:13) at Object.configure (/app/node_modules/zigbee-herdsman-converters/src/index.ts:141:25) at Configure.configure (/app/lib/extension/configure.ts:120:13) at EventEmitter.wrappedCallback (/app/lib/eventBus.ts:174:17)) Zigbee2MQTT:info 2024-02-18 22:52:23: Successfully changed options Zigbee2MQTT:info 2024-02-18 22:52:23: MQTT publish: topic 'zigbee2mqtt/bridge/response/options', payload '{"data":{"restart_required":false},"status":"ok","transaction":"tjlq7-1"}' Zigbee2MQTT:debug 2024-02-18 22:52:30: Received MQTT message on 'zigbee2mqtt/bridge/request/permit_join' with data '{"device":null,"time":254,"transaction":"tjlq7-2","value":true}' Zigbee2MQTT:info 2024-02-18 22:52:31: Zigbee: allowing new devices to join. Zigbee2MQTT:debug 2024-02-18 22:52:31: Received Zigbee message from 'Coordinator', type 'commandNotification', cluster 'greenPower', data '{"data":[25,15,2,11,254,0],"type":"Buffer"}' from endpoint 242 with groupID null, ignoring since it is from coordinator Zigbee2MQTT:info 2024-02-18 22:52:31: MQTT publish: topic 'zigbee2mqtt/bridge/response/permit_join', payload '{"data":{"time":254,"value":true},"status":"ok","transaction":"tjlq7-2"}' Zigbee2MQTT:debug 2024-02-18 22:52:31: Received Zigbee message from '0x54ef4410009a4274', type 'read', cluster 'genTime', data '["timeZone","time"]' from endpoint 1 with groupID 0 Zigbee2MQTT:debug 2024-02-18 22:52:43: Received Zigbee message from '0x00124b002236e95a', type 'attributeReport', cluster 'genOnOff', data '{"onOff":0}' from endpoint 1 with groupID 0 Zigbee2MQTT:info 2024-02-18 22:52:43: MQTT publish: topic 'zigbee2mqtt/0x00124b002236e95a', payload '{"device":{"applicationVersion":2,"dateCode":"20191113","friendlyName":"0x00124b002236e95a","hardwareVersion":1,"ieeeAddr":"0x00124b002236e95a","manufacturerID":0,"manufacturerName":"SONOFF","model":"BASICZBR3","networkAddress":22084,"powerSource":"Mains (single phase)","type":"Router","zclVersion":1},"linkquality":88,"state":"OFF"}' Zigbee2MQTT:debug 2024-02-18 22:52:53: Saving state to file /config/zigbee2mqtt/state.json Zigbee2MQTT:warn 2024-02-18 22:52:56: Device '0x54ef441000848e13' left the network Zigbee2MQTT:info 2024-02-18 22:52:57: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x54ef441000848e13","ieee_address":"0x54ef441000848e13"},"type":"device_leave"}' Zigbee2MQTT:debug 2024-02-18 22:53:02: Device '0x54ef441000848e13' reconnected Zigbee2MQTT:info 2024-02-18 22:53:02: MQTT publish: topic 'zigbee2mqtt/0x54ef441000848e13/availability', payload '{"state":"online"}' Zigbee2MQTT:info 2024-02-18 22:53:02: Device '0x54ef441000848e13' joined Zigbee2MQTT:info 2024-02-18 22:53:03: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x54ef441000848e13","ieee_address":"0x54ef441000848e13"},"type":"device_joined"}' Zigbee2MQTT:info 2024-02-18 22:53:03: Starting interview of '0x54ef441000848e13' Zigbee2MQTT:info 2024-02-18 22:53:04: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0x54ef441000848e13","ieee_address":"0x54ef441000848e13","status":"started"},"type":"device_interview"}' Zigbee2MQTT:debug 2024-02-18 22:53:04: Retrieving state of '0x54ef441000848e13' after reconnect Error: Failure send findKeyTableEntry:{"type":"Buffer","data":[135,0,255,0,117,19,142,132,0,16,68,239,84,1]} at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:646:23 at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20) at Driver.cleanupTClinkKey (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:419:24)

Reboot and Stopped again:

Zigbee2MQTT:debug 2024-02-18 23:08:42: Received MQTT message on 'homeassistant/update/0x54ef44100092676b/update/config' with data '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"},{"topic":"zigbee2mqtt/0x54ef44100092676b/availability","value_template":"{{ value_json.state }}"}],"availability_mode":"all","command_topic":"zigbee2mqtt/bridge/request/device/ota_update/update","device":{"identifiers":["zigbee2mqtt_0x54ef44100092676b"],"manufacturer":"Aqara","model":"TVOC air quality monitor (VOCKQJK11LM)","name":"0x54ef44100092676b","sw_version":"2020\u0000www.","via_device":"zigbee2mqtt_bridge_0x0c4314fffe57545e"},"device_class":"firmware","entity_category":"config","entity_picture":"https://github.com/Koenkk/zigbee2mqtt/raw/master/images/logo.png","json_attributes_template":"{\"in_progress\": {{ iif(value_json['update']['state'] == 'updating', 'true', 'false') }} }","json_attributes_topic":"zigbee2mqtt/0x54ef44100092676b","latest_version_template":"{{ value_json['update']['latest_version'] }}","latest_version_topic":"zigbee2mqtt/0x54ef44100092676b","name":null,"object_id":"0x54ef44100092676b","origin":{"name":"Zigbee2MQTT","sw":"1.35.3","url":"https://www.zigbee2mqtt.io"},"payload_install":"{\"id\": \"0x54ef44100092676b\"}","state_topic":"zigbee2mqtt/0x54ef44100092676b","unique_id":"0x54ef44100092676b_update_zigbee2mqtt","value_template":"{{ value_json['update']['installed_version'] }}"}' Zigbee2MQTT:debug 2024-02-18 23:08:42: Active device '0x84fd27fffed1394f' was last seen '0.18' minutes ago.

/app/node_modules/winston-transport/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-transport/node_modules/readable-stream/lib/_stream_writable.js:264:12) at File.Writable.write (/app/node_modules/winston-transport/node_modules/readable-stream/lib/_stream_writable.js:300:21) at DerivedLogger.ondata (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_readable.js:629:20) at DerivedLogger.emit (node:events:517:28) at DerivedLogger.Readable.read (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_readable.js:451:26) at flow (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_readable.js:858:34) at File.pipeOnDrainFunctionResult (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_readable.js:690:7) at File.emit (node:events:517:28) at onwriteDrain (/app/node_modules/winston-transport/node_modules/readable-stream/lib/_stream_writable.js:453:12) at afterWrite (/app/node_modules/winston-transport/node_modules/readable-stream/lib/_stream_writable.js:441:18)

Koenkk commented 9 months ago

But it looks like the /app/node_modules/winston-transport/node_modules/readable-stream/lib/_stream_writable.js:264 var er = new ERR_STREAM_WRITE_AFTER_END(); is gone now?

asan84 commented 9 months ago

But it looks like the /app/node_modules/winston-transport/node_modules/readable-stream/lib/_stream_writable.js:264 var er = new ERR_STREAM_WRITE_AFTER_END(); is gone now?

No. I've updated the post above.

Koenkk commented 9 months ago

Reboot and Stopped again: -> this will restart the addon and thus remove the changes, but before the reboot the problem didn't seem to happen?

asan84 commented 9 months ago

Maybe.

I can’t repeat it again because the process keeps stopping.

[23:27:49] INFO: Preparing to start... [23:27:53] INFO: Socat not enabled [23:28:11] INFO: Starting Zigbee2MQTT... Zigbee2MQTT:error 2024-02-18 23:29:19: Adapter disconnected, stopping Zigbee2MQTT:error 2024-02-18 23:29:20: Failed to stop Zigbee2MQTT

Koenkk commented 9 months ago

@asan84 this is probably caused by an issue with the new adapter implementation, soon this will be improved, keep an eye on https://github.com/Koenkk/zigbee-herdsman/pull/918

Nerivec commented 9 months ago

For the ezsp users, make sure you use the proper configuration for rtscts according to your adapter. For Skyconnect true, for Sonoff Dongle-E false (if the setting is omitted, then it is false by default). https://www.zigbee2mqtt.io/guide/configuration/adapter-settings.html

@asan84 from your first post, you are using a very old firmware version. That definitely could cause issues (note that you will have to re-pair everything after update; I wouldn't hope for anything else). https://darkxst.github.io/silabs-firmware-builder/

@Koenkk for the winston stuff, I found several open issues that seem to come and go over the years (in the repo and in packages using winston), but since I don't know winston... :wink:

Rookman2022 commented 9 months ago

Hello, I still have the same problem. I use the Skyconnect but if I set the rtscts parameter to "true", even version 135.1-1 no longer starts for me. Zigbee2MQTT version 1.35.1 commit: unknown Coordinator type EZSP v12 Coordinator version 7.3.2.0 build 212

With my current settings, version 135.1-1 runs without any problems.

This error message appears when I set rtscts to true: error 2024-02-19 11:25:01: Error while starting zigbee-herdsman error 2024-02-19 11:25:01: Failed to start zigbee error 2024-02-19 11:25:01: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions error 2024-02-19 11:25:01: Exiting... error 2024-02-19 11:25:02: Error: Failure send version:{"type": "Buffer", "data":[1,0,1,0,0,12]} at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:646:23 at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:35:20) at Ezsp.version (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:456:13) at Driver.startup (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:167:9) 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:109:27) at start (/app/index.js:107:5)

Nerivec commented 9 months ago

@Rookman2022 Can you try again with herdsman debug ON and provide the logs? https://www.zigbee2mqtt.io/guide/usage/debug.html#zigbee-herdsman-debug-logging

Also what firmware supplier are you using (Nabu Casa, darkxst, etc)?

Rookman2022 commented 9 months ago

I have tested again Version 135.1-1 also runs with "rtscts: true" after the update to 135.3-1 the error appears, see log. I have installed the firmware from Nabu Casa on my SkyConnect V7.3.2.0 build 212

LOG_z2m_135-3-1.txt

Nerivec commented 9 months ago

That would seem to indicate your SkyConnect does not like rtscts... strange, but you don't seem to be the only one... Does it work with 1.35.3-1 if you set rtscts: false (or remove the line entirely, it defaults to false if not provided)?

@kirovilya Do you have a SkyConnect to run some tests on this (I don't)? I'm wondering if serialport is not setting the flags, or if it's getting disabled for some reason (between port opening and NCP reset start)? I though the SkyConnect supported this... (can't seem to find any official info on it though...) https://serialport.io/docs/api-stream#get

kirovilya commented 9 months ago

I don't have a skyconnect. I checked on the flashed sticks of ZB-GW04. @Rookman2022 check on the current dev/edge version of z2m - I added a pause there and it should help solve the problem - it helped me

Rookman2022 commented 9 months ago

That would seem to indicate your SkyConnect does not like rtscts... strange, but you don't seem to be the only one... Does it work with 1.35.3-1 if you set rtscts: false (or remove the line entirely, it defaults to false if not provided)?

Under 135.1-1 it works with rtscts true and false under 135.2-1 and 135.3-1 neither.

Nerivec commented 9 months ago

This is a strange problem you are having.

With 1.35.2, that somewhat could make sense, if your adapter isn't supporting rtscts, before that (in 1.35.1), it would have been able to use xon/xoff, since both would have been enabled (which created problems with actual rtscts-enabled adapters). With 1.35.2, xon/xoff is only enabled if rtscts is false.

But from 1.35.2 to 1.35.3, there were no change to anything serial-related, and no change at all in ezsp... I would expect the behavior to be identical to 1.35.2 here...

Rookman2022 commented 9 months ago

Hello, the dev version runs in version 135.3 with rtscts: true without any problems so far

LOG:

info 2024-02-22 15:17:14: Logging to console and directory: '/config/zigbee2mqtt/log/2024-02-22.15-17-14' filename: log.txt info 2024-02-22 15:17:14: Starting Zigbee2MQTT version 1.35.3-dev (commit #22d3336) info 2024-02-22 15:17:14: Starting zigbee-herdsman (0.34.2) info 2024-02-22 15:17:23: zigbee-herdsman started (resumed) info 2024-02-22 15:17:23: Coordinator firmware version: '{"meta":{"maintrel":"2 ","majorrel":"7","minorrel":"3","product":12,"revision":"7.3.2.0 build 212"},"type":"EZSP v12"}' info 2024-02-22 15:17:23: Currently 93 devices are joined:

Nerivec commented 9 months ago

Looks like kirovilya's fix is working then. Good to know, thank you for the feedback!

PrzemsiMat commented 9 months ago

ZB-WG04 forks fine for all day with no restart, now i switch Sonoff Dongle V2 (EFR) from ZHA to z2m, we will see tomorrow. Grate job kirovilya

myllo commented 9 months ago

I am seeing similar symptoms after updating both the HA core to 2024.2.3 and Zigbee2mqtt to 1.35.3-1. Using Sonoff ZB Pro (ESP32 based) with latest Tasmota. I am using Supervised (supervisor-2024.02.0).

I have lost all Z2m connectivity due to Zigbee2mqtt stopping within 30 seconds from starting it. I see no errors on logs, and Tasmota console tells me "TCP: Got connection from 192.168.1.x", so at least it connects, but then something suddenly stops.

If the fix by kirovilya can be expected to cure this, please either advice how to implement it to the current system (mind you, cannot keep the zigbee2mqtt container running, seems to stop itself) or publish a fixed version for the larger public to use.

myllo commented 9 months ago

This is the log (referring above):

[11:30:40] INFO: Preparing to start... [11:30:40] INFO: Socat not enabled [11:30:41] INFO: Zigbee Herdsman debug logging enabled [11:30:42] INFO: Starting Zigbee2MQTT... 2024-02-25T09:30:49.416Z zigbee-herdsman:adapter Failed to validate path: 'Error: spawn udevadm ENOENT' 2024-02-25T09:30:49.423Z zigbee-herdsman:controller:log 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":{"path":"tcp://192.168.1.250:8888"},"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-02-25T09:30:49.425Z zigbee-herdsman:adapter:zStack:znp:log Opening TCP socket with 192.168.1.250:8888 2024-02-25T09:30:49.529Z zigbee-herdsman:adapter:zStack:znp:log Socket connected 2024-02-25T09:30:49.530Z zigbee-herdsman:adapter:zStack:znp:log Socket ready 2024-02-25T09:30:49.532Z zigbee-herdsman:adapter:zStack:znp:log Writing CC2530/CC2531 skip bootloader payload 2024-02-25T09:30:49.533Z zigbee-herdsman:adapter:zStack:unpi:writer --> buffer [239] 2024-02-25T09:30:50.537Z zigbee-herdsman:adapter:zStack:znp:log Skip bootloader for CC2652/CC1352 2024-02-25T09:30:50.542Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2024-02-25T09:30:50.546Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2024-02-25T09:30:56.554Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2024-02-25T09:30:56.556Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2024-02-25T09:31:02.561Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2024-02-25T09:31:02.561Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32]

myllo commented 9 months ago

I have just migrated from supervised to the latest HA OS (to not get caught with unsupported notice), using the backup from this morning. Unfortunately it did not solve the problem.

I suspect that this has something to do with the interplay between core 2024.2.3 and z2m 1.35.3-1, as it did not manifest until I had to reboot the Raspi 4.

myllo commented 9 months ago

A bit more data in the log now: as above , plus

Zigbee2MQTT:error 2024-02-25 18:18:05: Error while starting zigbee-herdsman Zigbee2MQTT:error 2024-02-25 18:18:05: Failed to start zigbee Zigbee2MQTT:error 2024-02-25 18:18:05: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions Zigbee2MQTT:error 2024-02-25 18:18:05: Exiting... Zigbee2MQTT:error 2024-02-25 18:18:05: Error: Failed to connect to the adapter (Error: SRSP - SYS - ping after 6000ms) at ZStackAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/adapter/zStackAdapter.ts:103:27) 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:109:27) at start (/app/index.js:107:5)

Nerivec commented 9 months ago

zigbee-herdsman:adapter:zStack:znp:log

@myllo If your adapter is EZSP based, then this is a problem, your logs show it is trying to use zStack. Specify it explicitly in your config (with the rest)

serial:
  adapter: ezsp

https://www.zigbee2mqtt.io/guide/configuration/adapter-settings.html

PS: Regarding kirovilya's fix, it will go live with next Z2M release (every 1st of the month), so it isn't far. But it is only for ezsp.

myllo commented 9 months ago

OK. So I have bumped into something else. Please take note.

My configuration for that part is

serial: port: tcp://192.168.1.xxx:8888

During the day, I have rolled back to Zigbee2Mqtt version 1.34.0-1. That works with my current settings now.

To me, a layman, it seems likely that the initial connection time is longer than allowed by the version 1.35.3, and version 1.34.0-1 either has more leeway with timeouts or the combination of z2m 1.34.0-1 and core 2023.11.3 ( that was my latest backup still available before the Jan 1, 2024, when z2m 1.35 first got rolled out.) together run slower and my adapter gets itself sorted out in time.

corporategoth commented 9 months ago

I would also recommend everyone chime in on https://github.com/home-assistant/core/pull/109030 This is a HA change to switch from using entity-based configuration to device-based configuration with HA. This will significantly reduce the number of configuration messages going back and forth, and drastically reduce the number of messages being send to/from HA. Which would reduce load/time spent doing that (using up the worker thread cycles).

Right now, that MR seems feature complete, the original author just put it back to draft. But I think with more input from others, he might actually push it forward again.

iotola commented 9 months ago

I have also had issues with starting Z2M in HA since about December and I concluded it had something to do with the significant amount of traffic at the start simply as I don't have a problem once it is started. I am using the Sonoff-E and found that reducing the concurrency setting from the default ("null") to 1 or 2 seems to slow the traffic down enough for it to start. I had thought it was the Zigbee traffic but having read about the large amount of MQTT traffic on startup it could well be that.

github-actions[bot] commented 8 months ago

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

jandr commented 1 month ago

I am getting a similar issue with Zigbee2MQTT 1.40.2. not sure if a new issue would be best or to revisit this one:

I am using a Conbee II adapter, and when starting up (/usr/bin/npm start within /opt/zigbee2mqtt), I am getting the following error: 

Starting Zigbee2MQTT without watchdog.
[2024-10-31 15:18:32] info:     z2m: Logging to console, file (filename: log.log)
[2024-10-31 15:18:32] info:     z2m: Starting Zigbee2MQTT version 1.40.2 (commit #e06848db)
[2024-10-31 15:18:32] info:     z2m: Starting zigbee-herdsman (2.1.3)
[2024-10-31 15:18:34] info:     zh:zstack:znp: Opening SerialPort with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":false,"autoOpen":false}
[2024-10-31 15:18:34] info:     zh:zstack:znp: Serialport opened
[2024-10-31 15:18:34] info:     zh:zstack:znp: Writing CC2530/CC2531 skip bootloader payload
[2024-10-31 15:18:35] info:     zh:zstack:znp: Skip bootloader for CC2652/CC1352
[2024-10-31 15:18:35] error:    z2m: Error while starting zigbee-herdsman
[2024-10-31 15:18:35] error:    z2m: Failed to start zigbee
[2024-10-31 15:18:35] error:    z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
[2024-10-31 15:18:35] error:    z2m: Exiting...
[2024-10-31 15:18:35] error:    z2m: Error: Error: Operation not supported, cannot set

/opt/zigbee2mqtt/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 (/opt/zigbee2mqtt/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:264:12)
    at DerivedLogger.Writable.write (/opt/zigbee2mqtt/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:300:21)
    at DerivedLogger.log (/opt/zigbee2mqtt/node_modules/winston/lib/winston/logger.js:231:12)
    at Logger.log (/opt/zigbee2mqtt/lib/util/logger.ts:198:25)
    at Logger.info (/opt/zigbee2mqtt/lib/util/logger.ts:211:14)
    at Znp.onPortClose (/opt/zigbee2mqtt/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/znp.ts:96:16)
    at Object.onceWrapper (node:events:632:26)
    at SerialPort.emit (node:events:529:35)
    at port.close.then.closing (/opt/zigbee2mqtt/node_modules/@serialport/stream/dist/index.js:242:18)

The device /dev/ttyACM0 is the ConBee II device (so the root of the issue is not that it points to a different device). The user under which zigbee2mqtt runs has read and write privileges on the device.

[ADDED CONTEXT]:

I am using Zigbee2MQTT inside a Proxmox container, and apparently someone is having the same issue: https://community.home-assistant.io/t/updated-zigbee2mqtt-in-proxmox-now-fails-to-start/787116/2

lorenzofattori commented 1 month ago

Same happening here with v1.40.2 via home assistant addon, HA running in a proxmox server:

[21:39:35] INFO: Preparing to start...
[21:39:35] INFO: Socat not enabled
[21:39:36] INFO: Starting Zigbee2MQTT...
Starting Zigbee2MQTT without watchdog.
[2024-11-01 21:39:37] info:     z2m: Logging to console, file (filename: log.log)
[2024-11-01 21:39:37] info:     z2m: Starting Zigbee2MQTT version 1.40.2 (commit #unknown)
[2024-11-01 21:39:37] info:     z2m: Starting zigbee-herdsman (2.1.3)
[2024-11-01 21:39:37] error:    zh:zstack:znp: Failed to determine if path is valid: 'Error: spawn udevadm ENOENT'
[2024-11-01 21:39:37] info:     zh:zstack:znp: Opening SerialPort with {"path":"/dev/serial/by-id/usb-ITEAD_SONOFF_Zigbee_3.0_USB_Dongle_Plus_V2_20240218163524-if00","baudRate":115200,"rtscts":false,"autoOpen":false}
[2024-11-01 21:39:37] info:     zh:zstack:znp: Serialport opened
[2024-11-01 21:39:37] info:     zh:zstack:znp: Writing CC2530/CC2531 skip bootloader payload
[2024-11-01 21:39:39] info:     zh:zstack:znp: Skip bootloader for CC2652/CC1352
[2024-11-01 21:39:39] error:    z2m: Error while starting zigbee-herdsman
[2024-11-01 21:39:39] error:    z2m: Failed to start zigbee
[2024-11-01 21:39:39] error:    z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
[2024-11-01 21:39:39] error:    z2m: Exiting...
[2024-11-01 21:39:39] error:    z2m: Error: Error: Not supported, cannot set

/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:198:25)
    at Logger.info (/app/lib/util/logger.ts:211:14)
    at Znp.onPortClose (/app/node_modules/zigbee-herdsman/src/adapter/z-stack/znp/znp.ts:96:16)
    at Object.onceWrapper (node:events:632:26)
    at SerialPort.emit (node:events:529:35)
    at port.close.then.closing (/app/node_modules/@serialport/stream/dist/index.js:242:18)`
lorenzofattori commented 1 month ago

and I just tried using a separate proxmox container, exactly the same error :(

MaxPohlRP commented 2 weeks ago

i have the same issue on homeassistant addon.