Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
asan84 opened this issue Feb 7, 2024 · 42 comments
Closed
Labels

Comments

@asan84
Copy link

asan84 commented Feb 7, 2024

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
Copy link

remove and insert the USB coordinator, it helped me

@asan84
Copy link
Author

asan84 commented Feb 8, 2024

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
Copy link

tm8 commented Feb 8, 2024

+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
Copy link

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
Copy link

tm8 commented Feb 8, 2024

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

@Rookman2022
Copy link

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

@gdesmott
Copy link

gdesmott commented Feb 8, 2024

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
Copy link
Contributor

Koenkk commented Feb 8, 2024

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

@tm8
Copy link

tm8 commented Feb 8, 2024

@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:
- 207
- 0
- XXXXXX
- 96
- 29
- 55
- XXXXXX
- 33
- 4
- XXXXXX
- 26
- 54
- 85
- 60
- 15
- 67
pan_id: 42440
ext_pan_id:
- 247
- XXXXX
- 82
- XXXXX
- 40
- 32
- XXXXXX
- XXXXXX
homeassistant_legacy_entity_attributes: false
legacy_api: false
legacy_availability_payload: false
log_level: info
log_syslog:
app_name: Zigbee2MQTT
eol: /n
host: localhost
localhost: localhost
path: /dev/log
pid: process.pid
port: 514
protocol: udp4
type: '5424'
last_seen: ISO_8601_local
mqtt:
server: mqtt://core-mosquitto:1883
user: addons
password: XXXXXXXX
port: /dev/ttyUSB0
frontend:
port: 8099
device_options:
legacy: false
devices:
'0x00158d0008d0b120':
friendly_name: WM Pufferspeicher | Heizraum
'0xc4988600000cac5e':
friendly_name: WC Licht 1
'0x0ceff6fffedfd53e':
friendly_name: HKT WC
'0x0017880106f90047':
friendly_name: HUE Schrank Wohnzimmer
'0x001788010331074e':
friendly_name: HUE Uhr Wohnzimmer
'0x0017880103316314':
friendly_name: HUE Ecke Couch Wohnzimmer
'0x001788010330ad16':
friendly_name: HUE Terrassentür Wohnzimmer
'0x0017880106fd5a92':
friendly_name: HUE TV Rechts Wohnzimmer
'0x0017880106fd59b2':
friendly_name: HUE TV Links Wohnzimmer
'0x001788010406f022':
friendly_name: HUE Strip Bad
'0xb0c7defffeeb39cd':
friendly_name: HKT Schlafzimmer
'0x3410f4fffeb2a850':
friendly_name: HKT Schlafzimmer 2
'0x0ceff6fffeb95b4f':
friendly_name: HKT Flur OG
'0x0ceff6fffedc7876':
friendly_name: HKT Bad OG
'0x0ceff6fffedd9439':
friendly_name: HKT Büro
'0x0ceff6fffedc9fbe':
friendly_name: HKT Küche
'0x000d6f0014f7de56':
friendly_name: CO Sensor Wohnzimmer
'0x001788010bcff5d8':
friendly_name: BM Schlafzimmer 2
'0x001788010bcfe674':
friendly_name: BM Philips HUE
'0x00158d0008d095ee':
friendly_name: WM Waschmaschine Trockner | Eingang UG
'0x00158d0008dffb06':
friendly_name: WM Hauptwasseranschluss | Abstellraum
'0x0ceff6fffeb95b07':
friendly_name: HKT Flur UG
'0x0ceff6fffedcbe0f':
friendly_name: HKT Fitnessraum
'0x0ceff6fffedfd47f':
friendly_name: HKT Bad UG
'0x0ceff6fffedca2a3':
friendly_name: HKT Gästezimmer
'0x000d6f001491b1cb':
friendly_name: CO Sensor Heizraum
'0x001788010d3572f7':
friendly_name: FB Philips HUE Dial 1 Büro
'0x804b50fffee0df75':
friendly_name: R2 L1 Licht Lounge
'0x804b50fffee2917f':
friendly_name: R4 L5 Licht Lounge
'0x804b50fffee273d1':
friendly_name: R2 L3 Licht Lounge
'0x804b50fffee27ace':
friendly_name: R1 L2 Licht Lounge
'0x804b50fffee0e01f':
friendly_name: R2 L2 Licht Lounge
'0xcc86ecfffe1c6095':
friendly_name: R1 L5 Licht Lounge
'0x804b50fffee273c5':
friendly_name: R4 L6 Licht Lounge
'0x804b50fffee27360':
friendly_name: R1 L6 Licht Lounge
'0x804b50fffee0e5b6':
friendly_name: R1 L3 Licht Lounge
'0x804b50fffee0e6d0':
friendly_name: R1 L1 Licht Lounge
'0xcc86ecfffe1d7732':
friendly_name: R4 L1 Licht Lounge
'0xc498860000da354c':
friendly_name: ACDC Lampe Licht Lounge
'0x804b50fffee0e28e':
friendly_name: R4 L3 Licht Lounge
'0x804b50fffee2781d':
friendly_name: R1 L4 Licht Lounge
'0x00178801097a2680':
friendly_name: R3 L1 Licht Lounge
'0x0017880109719b3a':
friendly_name: R3 L3 Licht Lounge
'0x00178801096fdc51':
friendly_name: R3 L2 Licht Lounge
'0x804b50fffee274e6':
friendly_name: R2 L4 Licht Lounge
'0x001788010b80e724':
friendly_name: HUE Leselicht Lounge
'0x00178801033251c4':
friendly_name: HUE Iris Lounge
'0x00124b002342e139':
friendly_name: BM Treppenhaus EG
'0x00124b0023adff17':
friendly_name: BM Treppenhaus DG
'0xcc86ecfffedb35e4':
friendly_name: Licht Treppenhaus OG-DG
'0x0017880102d54bab':
friendly_name: FB Philips HUE 1 WC
legacy: true
'0x001788010406bbbd':
friendly_name: HUE Strip Büro
'0x804b50fffee0e6f2':
friendly_name: R4 L2 Licht Lounge
'0x84fd27fffe698237':
friendly_name: R4 L4 Licht Lounge
'0x00178801096fc16a':
friendly_name: R3 L4 Licht Lounge
'0x001788010dd00b6f':
friendly_name: FB Philips HUE Dial 2 Lounge
'0x001788010d8bb2dc':
friendly_name: FB Philips HUE 2
ota:
ikea_ota_use_test_url: false
zigbee_ota_override_index_location: https://raw.githubusercontent.com/Koenkk/zigbee-OTA/master/index.json

@tm8
Copy link

tm8 commented Feb 8, 2024

I have two Sonoff Dongles:

  • Version P for Zigbee on Chanel 15
  • Version E for Thread on Chanel 25 (FIrmware is Flash only for Thread, not vor Multiprotocol)

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
Copy link
Author

asan84 commented Feb 9, 2024

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

configuration.zip

@Koenkk
Copy link
Contributor

Koenkk commented Feb 11, 2024

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
Copy link

tm8 commented Feb 11, 2024

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
Copy link

PrzemsiMat commented Feb 12, 2024

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

@asan84
Copy link
Author

asan84 commented Feb 16, 2024

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
Copy link
Contributor

Koenkk commented Feb 18, 2024

@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
Copy link
Author

asan84 commented Feb 18, 2024

@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
Copy link
Contributor

Koenkk commented Feb 18, 2024

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
Copy link
Author

asan84 commented Feb 18, 2024

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
Copy link
Contributor

Koenkk commented Feb 18, 2024

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
Copy link
Author

asan84 commented Feb 18, 2024

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
Copy link
Contributor

Koenkk commented Feb 18, 2024

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

@Nerivec
Copy link

Nerivec commented Feb 18, 2024

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

@Rookman2022
Copy link

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
Copy link

Nerivec commented Feb 19, 2024

@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
Copy link

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
Copy link

Nerivec commented Feb 20, 2024

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
Copy link

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
Copy link

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
Copy link

Nerivec commented Feb 21, 2024

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
Copy link

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
Copy link

Nerivec commented Feb 22, 2024

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

@PrzemsiMat
Copy link

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
Copy link

myllo commented Feb 25, 2024

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
Copy link

myllo commented Feb 25, 2024

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
Copy link

myllo commented Feb 25, 2024

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
Copy link

myllo commented Feb 25, 2024

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
Copy link

Nerivec commented Feb 25, 2024

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
Copy link

myllo commented Feb 25, 2024

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
Copy link

I would also recommend everyone chime in on home-assistant/core#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
Copy link

iotola commented Feb 29, 2024

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.

Copy link

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests