Koenkk / zigbee2mqtt

Zigbee 🐝 to MQTT bridge 🌉, get rid of your proprietary Zigbee bridges 🔨
https://www.zigbee2mqtt.io
GNU General Public License v3.0
11.84k stars 1.65k forks source link

Zigbee Dongle Port Shutdown and Home Assistant Crashes #23843

Open Option212 opened 3 weeks ago

Option212 commented 3 weeks ago

What happened?

Occasionally, the port on my Zigbee dongle shuts down (one to 5times a day). When this happens, restarting the service consistently causes Home Assistant to crash, resulting in lost logs. The workaround I've found is to disconnect (physically) and reconnect the adapter, followed by restarting the Zigbee2MQTT service.

Only one device is paired : ICT module for LINKY to Zigbee 3.0 counter ZLinky_TICLixee.

What did you expect to happen?

No response

How to reproduce it (minimal and precise)

No response

Zigbee2MQTT version

1.40.0-1

Adapter firmware version

7.4.1.0-zbdonglee-115200

Adapter

ZBdongle-E

Setup

Raspberry Pi 3 Model B

Debug log

2024-09-19 18:38:32] info: z2m: Stopped Zigbee2MQTT /app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:264 var er = new ERR_STREAM_WRITE_AFTER_END(); ^ Error: write after end at writeAfterEnd (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:264:12) at DerivedLogger.Writable.write (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:300:21) at DerivedLogger.log (/app/node_modules/winston/lib/winston/logger.js:231:12) at Logger.log (/app/lib/util/logger.ts:189:25) at Logger.error (/app/lib/util/logger.ts:194:14) at EventEmitter.wrappedCallback (/app/lib/eventBus.ts:176:24) [22:47:47] INFO: Preparing to start... [22:47:51] INFO: Socat not enabled [22:47:52] INFO: Enabled Zigbee2MQTT watchdog with value 'default' [22:47:59] INFO: Starting Zigbee2MQTT... Starting Zigbee2MQTT with watchdog (2000,60000,300000,900000,1800000,3600000). [2024-09-19 22:48:29] info: z2m: Logging to console, file (filename: log.log) [2024-09-19 22:48:40] info: z2m: Starting Zigbee2MQTT version 1.40.1 (commit #unknown) [2024-09-19 22:48:41] info: z2m: Starting zigbee-herdsman (0.57.3) [2024-09-19 22:49:08] info: zh:ember: Using default stack config. [2024-09-19 22:49:08] info: zh:ember: ======== Ember Adapter Starting ======== [2024-09-19 22:49:08] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-09-19 22:49:08] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-09-19 22:49:08] info: zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control. [2024-09-19 22:49:09] info: zh:ember:uart:ash: Serial port opened [2024-09-19 22:49:09] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-09-19 22:49:10] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-09-19 22:49:10] info: zh:ember:uart:ash: ======== ASH started ======== [2024-09-19 22:49:10] info: zh:ember:ezsp: ======== EZSP started ======== [2024-09-19 22:49:11] info: zh:ember: Adapter EZSP protocol version (13) lower than Host. Switched. [2024-09-19 22:49:11] info: zh:ember: Adapter version info: {"ezsp":13,"revision":"7.4.1 [GA]","build":0,"major":7,"minor":4,"patch":1,"special":0,"type":170} [2024-09-19 22:49:11] info: zh:ember: [STACK STATUS] Network up. [2024-09-19 22:49:11] info: zh:ember: [INIT TC] Adapter network matches config. [2024-09-19 22:49:11] info: zh:ember: [CONCENTRATOR] Started source route discovery. 1247ms until next broadcast. [2024-09-19 22:49:11] info: z2m: zigbee-herdsman started (resumed) [2024-09-19 22:49:11] info: z2m: Coordinator firmware version: '{"meta":{"build":0,"ezsp":13,"major":7,"minor":4,"patch":1,"revision":"7.4.1 [GA]","special":0,"type":170},"type":"EmberZNet"}' [2024-09-19 22:49:11] info: z2m: Lixee (0x00158d0005d24ff7): ZLinky_TIC - LiXee Lixee ZLinky (Router) [2024-09-19 22:49:11] info: z2m: Currently 1 devices are joined. [2024-09-19 22:49:11] info: z2m: Zigbee: disabling joining new devices. [2024-09-19 22:49:12] info: z2m: Connecting to MQTT server at mqtt://core-mosquitto:1883 [2024-09-19 22:49:18] info: z2m: Connected to MQTT server [2024-09-19 22:49:18] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload '{"state":"online"}' [2024-09-19 22:49:35] error: zh:ember:ezsp: ERROR Transaction failure; status=ASH_ERROR_TIMEOUTS. Last Frame: [FRAME: ID=54:"SEND_BROADCAST" Seq=38 Len=7]. [2024-09-19 22:49:35] error: zh:ember: Adapter fatal error: ASH_ERROR_TIMEOUTS [2024-09-19 22:49:35] info: zh:ember:uart:ash: ASH COUNTERS since last clear: [2024-09-19 22:49:35] info: zh:ember:uart:ash: Total frames: RX=45, TX=84 [2024-09-19 22:49:35] info: zh:ember:uart:ash: Cancelled : RX=0, TX=0 [2024-09-19 22:49:35] info: zh:ember:uart:ash: DATA frames : RX=43, TX=40 [2024-09-19 22:49:35] info: zh:ember:uart:ash: DATA bytes : RX=403, TX=440 [2024-09-19 22:49:35] info: zh:ember:uart:ash: Retry frames: RX=1, TX=0 [2024-09-19 22:49:35] info: zh:ember:uart:ash: ACK frames : RX=0, TX=43 [2024-09-19 22:49:35] info: zh:ember:uart:ash: NAK frames : RX=0, TX=0 [2024-09-19 22:49:35] info: zh:ember:uart:ash: nRdy frames : RX=0, TX=0 [2024-09-19 22:49:35] info: zh:ember:uart:ash: CRC errors : RX=0 [2024-09-19 22:49:35] info: zh:ember:uart:ash: Comm errors : RX=0 [2024-09-19 22:49:35] info: zh:ember:uart:ash: Length < minimum: RX=0 [2024-09-19 22:49:35] info: zh:ember:uart:ash: Length > maximum: RX=0 [2024-09-19 22:49:35] info: zh:ember:uart:ash: Bad controls : RX=0 [2024-09-19 22:49:35] info: zh:ember:uart:ash: Bad lengths : RX=0 [2024-09-19 22:49:35] info: zh:ember:uart:ash: Bad ACK numbers : RX=0 [2024-09-19 22:49:35] info: zh:ember:uart:ash: Out of buffers : RX=0 [2024-09-19 22:49:35] info: zh:ember:uart:ash: Retry dupes : RX=1 [2024-09-19 22:49:35] info: zh:ember:uart:ash: Out of sequence : RX=0 [2024-09-19 22:49:35] info: zh:ember:uart:ash: ACK timeouts : RX=0 [2024-09-19 22:49:37] warning: zhc:lixee: Failed to read zigbee attributes: Error: ZCL command 0x00158d0005d24ff7/1 liXeePrivate.read(["linkyMode","currentTarif"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"manufacturerCode":null,"writeUndiv":false}) failed (~x~> [ZCL to=50008] Failed to send request with status=FAIL.) [2024-09-19 22:49:40] info: z2m: Started frontend on port 8099 [2024-09-19 22:49:40] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload '{"state":"online"}' [2024-09-19 22:49:40] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Lixee', payload '{"MOTDETAT":null,"active_register_tier_delivered":"HPJB","apparent_power":340,"available_power":30,"current_summ_delivered":8061.501,"current_tarif":"BBR(","current_tier1_summ_delivered":2452.524,"current_tier2_summ_delivered":5608.977,"current_tier3_summ_delivered":0,"current_tier4_summ_delivered":0,"current_tier5_summ_delivered":0,"current_tier6_summ_delivered":0,"linkquality":220,"meter_serial_number":"042164280783","mot_d_etat":"000000","rms_current":2,"rms_current_max":90,"schedule_h_p_h_c":0,"start_notice_e_j_p":0,"tomorrow_color":"----","update":{"installed_version":14,"latest_version":14,"state":"idle"},"update_available":null,"warn_d_p_s":0}' [2024-09-19 22:49:40] info: z2m: Zigbee2MQTT started! [2024-09-19 22:49:41] error: zh:ember:uart:ash: Received ERROR from adapter, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT. [2024-09-19 22:49:41] error: zh:ember:uart:ash: ASH disconnected | Adapter status: ASH_NCP_FATAL_ERROR [2024-09-19 22:49:41] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR. [2024-09-19 22:49:41] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Lixee', payload '{"MOTDETAT":null,"active_register_tier_delivered":"HPJB","apparent_power":340,"available_power":30,"current_summ_delivered":8061.501,"current_tarif":"BBR(","current_tier1_summ_delivered":2452.524,"current_tier2_summ_delivered":5608.977,"current_tier3_summ_delivered":0,"current_tier4_summ_delivered":0,"current_tier5_summ_delivered":0,"current_tier6_summ_delivered":0,"linkquality":216,"meter_serial_number":"042164280783","mot_d_etat":"000000","rms_current":2,"rms_current_max":90,"schedule_h_p_h_c":0,"start_notice_e_j_p":0,"tomorrow_color":"----","update":{"installed_version":14,"latest_version":14,"state":"idle"},"update_available":null,"warn_d_p_s":0}' [2024-09-19 22:49:41] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR. [2024-09-19 22:49:41] info: zh:ember:uart:ash: Port closed. [2024-09-19 22:49:41] info: zh:ember:uart:ash: ======== ASH stopped ======== [2024-09-19 22:49:41] info: zh:ember:ezsp: ======== EZSP stopped ======== [2024-09-19 22:49:41] info: zh:ember: ======== Ember Adapter Stopped ======== [2024-09-19 22:49:41] error: z2m: Adapter disconnected, stopping [2024-09-19 22:49:42] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload '{"state":"offline"}' [2024-09-19 22:49:42] info: z2m: Disconnecting from MQTT server [2024-09-19 22:49:42] info: z2m: Stopping zigbee-herdsman... [2024-09-19 22:49:43] info: z2m: Stopped zigbee-herdsman [2024-09-19 22:49:43] info: z2m: Stopped Zigbee2MQTT WATCHDOG: Waiting 0.03333333333333333min before next start try.

/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:264 var er = new ERR_STREAM_WRITE_AFTER_END(); ^ Error: write after end at writeAfterEnd (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:264:12) at DerivedLogger.Writable.write (/app/node_modules/winston/node_modules/readable-stream/lib/_stream_writable.js:300:21) at DerivedLogger.log (/app/node_modules/winston/lib/winston/logger.js:231:12) at Logger.log (/app/lib/util/logger.ts:189:25) at Logger.error (/app/lib/util/logger.ts:194:14) at MqttClient. (/app/lib/mqtt.ts:115:24) at MqttClient.emit (node:events:529:35) at MqttClient._checkDisconnecting (/app/node_modules/mqtt/src/lib/client.ts:1701:10) at MqttClient.unsubscribe (/app/node_modules/mqtt/src/lib/client.ts:1343:12) at MQTT.unsubscribe (/app/lib/mqtt.ts:140:21)

Extra log : log_1.txt log_error_zigbee2mqtt.txt

nlhomme commented 3 weeks ago

I don't have logs to show but I also experience a very similar issue, with the same zigbee dongle, the same zigbee2mqtt release

Option212 commented 6 days ago

Could be a regression in linux kernel 6.6 used by HA. Issues tracked by https://github.com/raspberrypi/linux/issues/6172.

I'm sharing the same conclusion to solve the issue :

  1. stop z2m add-on and don't let it start at HA start
  2. unplug the dongle
  3. restart host
  4. wait some minutes after restart
  5. plug the dongle
  6. start z2m