Koenkk / zigbee2mqtt

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

SkyConnect Crashes on v1.35, OK on v1.34 and earlier #20868

Open droans opened 7 months ago

droans commented 7 months ago

What happened?

With v1.35.0/1.35.1, I've been receiving the sendZclFrameToEndpointInternal error. Unlike similar issue reports, mine was not occurring due to my config pointing at the wrong device.

However, based on the information in those posts, I set Z2M to collect the Zigbee-Herdsman debug logs. The first two files are the complete logs. The third file is a truncated log with the logs up until the devices are identified and the logs beginning right before the error occurred. Error messages begin on line 82227 in the second file.

log.part1.txt log.part2.txt truncated_log.txt

When this error occurs, Z2M will not work until I restart the service. The error showed up in my Z2M logs as below and would show for all my router devices:

warn  2024-01-17 19:40:08: Failed to ping 'Chaise Light' (attempt 1/2, Read 0x001788010311daf4/11 genBasic(["zclVersion"], {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disable
Recovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (sendZclFrameToEndpointInternal error))
warn  2024-01-17 19:40:11: Failed to ping 'Chaise Light' (attempt 2/2, Read 0x001788010311daf4/11 genBasic(["zclVersion"], {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (sendZclFrameToEndpointInternal error))
info  2024-01-17 19:40:14: MQTT publish: topic 'zigbee2mqtt2/Chaise Light/availability', payload '{"state":"offline"}'

When zigbee-herdsman debug logging is enabled, I was able to receive more information:

2024-01-18T00:37:44.119Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2024-01-18T00:37:44.119Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null
2024-01-18T00:37:44.119Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"nop","_id_":5,"_isRequest_":true}
2024-01-18T00:37:44.119Z zigbee-herdsman:adapter:ezsp:uart --> DATA (1,7,0): f900010500
2024-01-18T00:37:44.119Z zigbee-herdsman:adapter:ezsp:uart --> [17bb21a9512ac4457e]
2024-01-18T00:37:44.119Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (2)
2024-01-18T00:37:46.121Z zigbee-herdsman:adapter:ezsp:uart --> Error: Error: {"sequence":2} after 2000ms
2024-01-18T00:37:46.121Z zigbee-herdsman:adapter:ezsp:uart -!- break waiting (2)
2024-01-18T00:37:46.121Z zigbee-herdsman:adapter:ezsp:uart Can't send DATA frame (1,7,0): f900010500
2024-01-18T00:37:46.621Z zigbee-herdsman:adapter:ezsp:uart ->> DATA (1,7,1): f900010500
2024-01-18T00:37:46.621Z zigbee-herdsman:adapter:ezsp:uart --> [1fbb21a9512ac9077e]
2024-01-18T00:37:46.621Z zigbee-herdsman:adapter:ezsp:uart -?- rewaiting (2)
2024-01-18T00:37:48.623Z zigbee-herdsman:adapter:ezsp:uart --> Error: Error: {"sequence":2} after 2000ms
2024-01-18T00:37:48.623Z zigbee-herdsman:adapter:ezsp:uart -!- break rewaiting (2)
2024-01-18T00:37:48.623Z zigbee-herdsman:adapter:ezsp:uart Can't resend DATA frame (1,7,1): f900010500
2024-01-18T00:37:48.623Z zigbee-herdsman:adapter:ezsp:driv Reset connection. Try 0
2024-01-18T00:37:48.623Z zigbee-herdsman:adapter:ezsp:driv Stop driver
2024-01-18T00:37:48.624Z zigbee-herdsman:adapter:ezsp:ezsp Stop ezsp
2024-01-18T00:37:48.659Z zigbee-herdsman:adapter:ezsp:erro Watchdog heartbeat timeout Error: Failure send nop:{"type":"Buffer","data":[249,0,1,5,0]}
    at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:562:23
    at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32)
2024-01-18T00:37:48.664Z zigbee-herdsman:adapter:ezsp:uart Port closed
2024-01-18T00:37:48.664Z zigbee-herdsman:adapter:ezsp:ezsp Close ezsp
2024-01-18T00:37:48.664Z zigbee-herdsman:adapter:ezsp:driv Close driver
2024-01-18T00:37:48.664Z zigbee-herdsman:adapter:ezsp:ezsp Close ezsp
2024-01-18T00:37:48.664Z zigbee-herdsman:adapter:ezsp:driv Close driver
2024-01-18T00:37:49.666Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_d4b930fb36d5ec118a8e1fb1a1ca919a-if00-port0","baudRate":115200,"rtscts":true,"autoOpen":false}
2024-01-18T00:37:49.688Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 1 error: Error: Error while opening serialport 'Error: Error: I/O error, cannot open /dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_d4b930fb36d5ec118a8e1fb1a1ca919a-if00-port0'
    at SerialPort.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:94:28)
    at SerialPort._error (/app/node_modules/@serialport/stream/dist/index.js:82:22)
    at /app/node_modules/@serialport/stream/dist/index.js:118:18
2024-01-18T00:37:54.688Z zigbee-herdsman:adapter:ezsp:ezsp Next attempt 2
2024-01-18T00:37:54.689Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_d4b930fb36d5ec118a8e1fb1a1ca919a-if00-port0","baudRate":115200,"rtscts":true,"autoOpen":false}
2024-01-18T00:37:54.689Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 2 error: Error: Error while opening serialport 'Error: Error: No such file or directory, cannot open /dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_d4b930fb36d5ec118a8e1fb1a1ca919a-if00-port0'
    at SerialPort.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:94:28)
    at SerialPort._error (/app/node_modules/@serialport/stream/dist/index.js:82:22)
    at /app/node_modules/@serialport/stream/dist/index.js:118:18
2024-01-18T00:37:59.692Z zigbee-herdsman:adapter:ezsp:ezsp Next attempt 3
2024-01-18T00:37:59.692Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_d4b930fb36d5ec118a8e1fb1a1ca919a-if00-port0","baudRate":115200,"rtscts":true,"autoOpen":false}
2024-01-18T00:37:59.693Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 3 error: Error: Error while opening serialport 'Error: Error: No such file or directory, cannot open /dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_d4b930fb36d5ec118a8e1fb1a1ca919a-if00-port0'
    at SerialPort.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:94:28)
    at SerialPort._error (/app/node_modules/@serialport/stream/dist/index.js:82:22)
    at /app/node_modules/@serialport/stream/dist/index.js:118:18
2024-01-18T00:38:04.693Z zigbee-herdsman:adapter:ezsp:ezsp Next attempt 4
2024-01-18T00:38:04.693Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_d4b930fb36d5ec118a8e1fb1a1ca919a-if00-port0","baudRate":115200,"rtscts":true,"autoOpen":false}
2024-01-18T00:38:04.694Z zigbee-herdsman:adapter:ezsp:erro Connection attempt 4 error: Error: Error while opening serialport 'Error: Error: No such file or directory, cannot open /dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_d4b930fb36d5ec118a8e1fb1a1ca919a-if00-port0'
    at SerialPort.<anonymous> (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:94:28)
    at SerialPort._error (/app/node_modules/@serialport/stream/dist/index.js:82:22)
    at /app/node_modules/@serialport/stream/dist/index.js:118:18
2024-01-18T00:38:09.695Z zigbee-herdsman:adapter:ezsp:ezsp Next attempt 5
2024-01-18T00:38:09.709Z zigbee-herdsman:adapter:ezsp:erro Reset error Error: Failure to connect
    at Ezsp.connect (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:277:19)
    at Driver.startup (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:139:9)
    at Driver.onReset (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/driver.ts:111:17)
2024-01-18T00:38:09.709Z zigbee-herdsman:adapter:ezsp:driv Pause 10sec before try 1
2024-01-18T00:38:19.715Z zigbee-herdsman:adapter:ezsp:driv Reset connection. Try 1
2024-01-18T00:38:19.715Z zigbee-herdsman:adapter:ezsp:driv Stop driver
2024-01-18T00:38:19.715Z zigbee-herdsman:adapter:ezsp:ezsp Stop ezsp
2024-01-18T00:38:19.715Z zigbee-herdsman:adapter:ezsp:ezsp Close ezsp
2024-01-18T00:38:19.715Z zigbee-herdsman:adapter:ezsp:driv Close driver

To get more information, I pulled the kernel logs. The attached log is filtered on the relevant lines. The logs below are filtered on lines which are more unique.

Jan 17 19:37:43 server kernel: [887812.694496] usb 1-3.3: clear tt 1 (9052) error -71
Jan 17 19:37:43 server kernel: [887812.694744] usb 1-3.3: clear tt 1 (9042) error -71
...
Jan 17 19:37:44 server kernel: [887812.977357] cp210x ttyUSB0: usb_serial_generic_write_bulk_callback - nonzero urb status: -71
Jan 17 19:37:44 server kernel: [887812.979796] usb 1-3.3: clear tt 1 (9042) error -71
Jan 17 19:37:44 server kernel: [887812.979945] usb 1-3.3: clear tt 1 (1042) error -71
...

Jan 17 19:37:48 server kernel: [887817.519120] cp210x ttyUSB0: failed to get comm status: -71
Jan 17 19:37:48 server kernel: [887817.519375] usb 1-3.3: clear tt 1 (9042) error -71
Jan 17 19:37:48 server kernel: [887817.519622] usb 1-3.3: clear tt 1 (8040) error -71
Jan 17 19:37:48 server kernel: [887817.519795] usb 1-3.3: clear tt 1 (9042) error -71
Jan 17 19:37:48 server kernel: [887817.519799] cp210x ttyUSB0: failed get req 0x14 size 16 status: -71
Jan 17 19:37:48 server kernel: [887817.519915] usb 1-3.3: clear tt 1 (8040) error -71
Jan 17 19:37:48 server kernel: [887817.520127] usb 1-3.3: clear tt 1 (9042) error -71
Jan 17 19:37:48 server kernel: [887817.520168] cp210x ttyUSB0: failed set request 0x12 status: -71
Jan 17 19:37:48 server kernel: [887817.520373] usb 1-3.3: clear tt 1 (0040) error -71
Jan 17 19:37:48 server kernel: [887817.520879] cp210x ttyUSB0: failed set request 0x0 status: -71
...

Jan 17 19:37:49 server kernel: [887818.525847] cp210x ttyUSB0: failed set request 0x0 status: -71
Jan 17 19:37:49 server kernel: [887818.525854] cp210x ttyUSB0: cp210x_open - Unable to enable UART

Jan 17 19:37:54 server kernel: [887823.208486] usb 1-3.3.1: USB disconnect, device number 38
Jan 17 19:37:54 server kernel: [887823.208724] cp210x ttyUSB0: cp210x converter now disconnected from ttyUSB0
Jan 17 19:37:54 server kernel: [887823.209063] cp210x 1-3.3.1:1.0: device disconnected
Jan 17 19:37:54 server kernel: [887823.336401] usb 1-3.3: reset high-speed USB device number 37 using xhci_hcd
Jan 17 19:37:54 server kernel: [887823.416697] usb 1-3.3: device descriptor read/64, error -71
Jan 17 19:37:54 server kernel: [887823.612694] usb 1-3.3: device descriptor read/64, error -71
Jan 17 19:37:54 server kernel: [887823.804694] usb 1-3.3: reset high-speed USB device number 37 using xhci_hcd
Jan 17 19:37:55 server kernel: [887823.884692] usb 1-3.3: device descriptor read/64, error -71
Jan 17 19:37:55 server kernel: [887824.084698] usb 1-3.3: device descriptor read/64, error -71
Jan 17 19:37:55 server kernel: [887824.280686] usb 1-3.3: reset high-speed USB device number 37 using xhci_hcd
Jan 17 19:37:55 server kernel: [887824.280718] usb 1-3.3: Device not responding to setup address.
Jan 17 19:37:55 server kernel: [887824.488702] usb 1-3.3: Device not responding to setup address.
Jan 17 19:37:55 server kernel: [887824.700660] usb 1-3.3: device not accepting address 37, error -71
Jan 17 19:37:55 server kernel: [887824.780670] usb 1-3.3: reset high-speed USB device number 37 using xhci_hcd
Jan 17 19:37:55 server kernel: [887824.780714] usb 1-3.3: Device not responding to setup address.
Jan 17 19:37:56 server kernel: [887824.988696] usb 1-3.3: Device not responding to setup address.
Jan 17 19:37:56 server kernel: [887825.196646] usb 1-3.3: device not accepting address 37, error -71
Jan 17 19:37:56 server kernel: [887825.198594] usb 1-3.3: USB disconnect, device number 37
Jan 17 19:37:56 server kernel: [887825.384654] usb 1-3.3: new high-speed USB device number 40 using xhci_hcd
Jan 17 19:37:56 server kernel: [887825.486339] usb 1-3.3: New USB device found, idVendor=214b, idProduct=7250, bcdDevice= 1.00
Jan 17 19:37:56 server kernel: [887825.486344] usb 1-3.3: New USB device strings: Mfr=0, Product=1, SerialNumber=0
Jan 17 19:37:56 server kernel: [887825.486347] usb 1-3.3: Product: USB2.0 HUB
Jan 17 19:37:56 server kernel: [887825.544551] hub 1-3.3:1.0: USB hub found
Jan 17 19:37:56 server kernel: [887825.544714] hub 1-3.3:1.0: 4 ports detected
Jan 17 19:37:56 server kernel: [887825.836641] usb 1-3.3.1: new full-speed USB device number 41 using xhci_hcd
Jan 17 19:37:57 server kernel: [887825.959215] usb 1-3.3.1: New USB device found, idVendor=10c4, idProduct=ea60, bcdDevice= 1.00
Jan 17 19:37:57 server kernel: [887825.959220] usb 1-3.3.1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jan 17 19:37:57 server kernel: [887825.959222] usb 1-3.3.1: Product: SkyConnect v1.0
Jan 17 19:37:57 server kernel: [887825.959224] usb 1-3.3.1: Manufacturer: Nabu Casa
Jan 17 19:37:57 server kernel: [887825.959225] usb 1-3.3.1: SerialNumber: d4b930fb36d5ec118a8e1fb1a1ca919a
Jan 17 19:37:57 server kernel: [887825.961323] cp210x 1-3.3.1:1.0: cp210x converter detected
Jan 17 19:37:57 server kernel: [887825.971608] usb 1-3.3.1: cp210x converter now attached to ttyUSB0

This is not an issue that occurs on v1.34.0 or earlier. Please let me know if you need any more information.


Additional info:

Configuration:

permit_join: false
availability: true
serial:
  adapter: ezsp
  port: >-
    /dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_d4b930fb36d5ec118a8e1fb1a1ca919a-if00-port0
  baudrate: 115200
  rtscts: true
mqtt:
  base_topic: zigbee2mqtt2
  server: mqtt://XXX.XXX.XXX.XXX
  user: zigbee2mqtt2
  password: XXXXXXXXXXXXXX
  keepalive: 60
  reject_unauthorized: false
  version: 4
  include_device_information: true
advanced:
  pan_id: XXXX
  ikea_ota_use_test_url: true
  channel: 25
  network_key:
    - XXX
    - XXX
    - XXX
    - XXX
    - XXX
    - XXX
    - XXX
    - XXX
    - XXX
    - XXX
    - XXX
    - XXX
    - XXX
    - XXX
    - XXX
    - XXX
  log_syslog:
    app_name: Zigbee2MQTT
    eol: /n
    host: localhost
    localhost: localhost
    path: /dev/log
    pid: process.pid
    port: 123
    protocol: tcp4
    type: '5424'
  legacy_availability_payload: false
  last_seen: ISO_8601
  homeassistant_legacy_entity_attributes: false
  legacy_api: false
  log_level: info
frontend:
  port: 4980
homeassistant:
  status_topic: homeassistant/status
  legacy_entity_attributes: true
device_options:
  legacy: false
devices:
  ...
groups:
  ...
ota:
  ikea_ota_use_test_url: false

Docker-Compose:

services:
  zigbee2mqtt:
    container_name: zigbee2mqtt
    # image: koenkk/zigbee2mqtt:1.34.0
    image: koenkk/zigbee2mqtt
    volumes:
      - /run/udev:/run/udev:ro
      - ${SMART_DIR_LOCAL}/zigbee2mqtt2/data:/app/data
      - /dev/serial/by-id:/dev/serial/by-id
    devices:
      - /dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_d4b930fb36d5ec118a8e1fb1a1ca919a-if00-port0:/dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_d4b930fb36d5ec118a8e1fb1a1ca919a-if00-port0
    ports:
      - 27080:4980
    privileged: true
    restart: always
    depends_on:
      mqtt:
        condition: service_started
        restart: false
      homeassistant:
        condition: service_started
        restart: true
    environment: 
      TZ: ${TZ}
      PUID: ${PUID}
      PGID: ${PGID}
      LOG4J_FORMAT_MSG_NO_LOOKUPS: "true"
      DEBUG: zigbee-herdsman*

What did you expect to happen?

The Zigbee adapter should not crash.

How to reproduce it (minimal and precise)

Use SkyConnect (and possibly other EZSP adapters?). Run v1.35.0 or v1.35.1 and wait. It can take between a few minutes and 24 hours to crash.

Zigbee2MQTT version

1.35.0

Adapter firmware version

7.3.2.0 build 212, Gecko SDK v4.3.2.0

Adapter

SkyConnect

Setup

Z2M Docker

Debug log

See above

TokoTSP commented 7 months ago

I have the same issue. About onse a day randomly I start getting this error: Exception while calling fromZigbee converter: Command 0x70ac08fffe316a12/1 manuSpecificTuya.mcuGatewayConnectionStatus({"payloadSize":1,"payload":1}, {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (sendZclFrameToEndpointInternal error)} After some time later the whole Z2M stop wokring and I not receiving information from any of my sensors (I have 43 zigbees). After manual restart it Zibee2MQTT it works again.

j4m3s commented 7 months ago

I have the issue with 1.35 too - though I don't see anything in the dmesg logs. I'm using the Sonoff dongle. I tried replacing the USB extension cable in case it was that but it made no difference.

In my case it fails frequently, often multiple times in the day, and it's not picked up by the container watchdog - it just stops working reporting or updating devices.

I've rolled back to 1.34 and everything has been stable since.

Koenkk commented 7 months ago

@Nerivec is this something you could check?

Nerivec commented 7 months ago

I don't think this is EZSP-related. Comparing Z2M versions 1.34.0...1.35.1, herdsman went from v0.25.0...v0.30.0. The only change to the EZSP code in all that, is the missing parentheses in init from a while back. (And I doubt a potential problem with converters would go as far as crashing the coordinator completely.)

@droans That error -71 in the kernel logs seems to be related to USB suspend. Could something have changed in your system roughly at the same time you updated Z2M (or because you updated you triggered some other update, like the USB driver)? A USB power issue seems to be the second cause of error -71...

droans commented 7 months ago

@Nerivec Negative.

The coordinator only crashes on 1.35.0/1.35.1. I've been on 1.34 since with no issues but experience the crash within a few hours after upgrading to 1.35.

Nerivec commented 7 months ago

I don't know what system you are using exactly, but you could have restored a pre-breaking-update state when you rolled back (as in, an update that happened alongside Z2M's that also got reversed when you went back to 1.34)?

I can see this in the Dockerfile that changed and could affect the underlaying hardware, even though it's only a patch version...

-FROM alpine:3.18.4 as base
+FROM alpine:3.18.5 as base

https://git.alpinelinux.org/aports/log/?h=v3.18.5 @Koenkk Do you follow the changes there? (It's a long list 😅)

Last resort... If you are comfortable/familiar with the swap, you could always try the EDGE version, it should fix quite a few EZSP issues in the init/reset logic. But since the versions you mentioned don't bring any difference to EZSP I doubt it would make... well, a difference...

Koenkk commented 7 months ago

@droans are you using the z2m docker container or the z2m HA docker container (HA addon)

droans commented 7 months ago

Docker on Ubuntu 22.04.

j4m3s commented 7 months ago

In case it's of use I'm using haos on a pi and was seeing the frequent crashes until I rolled back to 1.34 :) No USB issues in dmesg on my side though (and using the Sonoff dongle).

On Sun, 28 Jan 2024, 20:01 droans, @.***> wrote:

Docker on Ubuntu 22.04.

— Reply to this email directly, view it on GitHub https://github.com/Koenkk/zigbee2mqtt/issues/20868#issuecomment-1913705986, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAPIBE7GRPHOC5B2FUPO5ALYQ2VCXAVCNFSM6AAAAABCAMJKEWVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMYTSMJTG4YDKOJYGY . You are receiving this because you are subscribed to this thread.Message ID: @.***>

Nerivec commented 7 months ago

@j4m3s Dongle E or Dongle P?

I'm assuming E since the original post was about EZSP. I have the Dongle E on HAOS, but on an Intel NUC. I didn't get a single error (much less crash) since I updated to 1.35, been running ever since... It is plugged into a USB3.0 port with a decent cable length (though it used to sit right next to the NUC without issue either).

What's the firmware version of your adapter? If you are on 6.x.x try going to 7.3.x. I've had it running for about three months now, no issue. 6 is getting old... 7.4.0 will get support in next release (only EDGE right now)! https://darkxst.github.io/silabs-firmware-builder/

droans commented 7 months ago

@Nerivec

I've been running the SkyConnect 7.3.2.0 for months now unfortunately. I use a long USB extension cable with a USB 2.0 hub at the end of it. My Zigbee and Z-Wave dongles are plugged into short extension cables attached to that.

I've built 1.35.1 locally with Alpine v3.18.4 since that seems to be the most likely issue... I'll see if it still crashes.

Nerivec commented 7 months ago

I've built 1.35.1 locally with Alpine v3.18.4 since that seems to be the most likely issue... I'll see if it still crashes.

Great! Let me know. PS: You should also be able to check USB power with lsusb -v, with a bit of luck, you might see something relevant. Could be the hub is not getting enough juice... (as to why that would happen only with latest version...)

j4m3s commented 7 months ago

@Nerivec yes Dongle-E and you're dead right, firmware version 6.10.3.0 build 297. I'm upgrading to 7.3.1.0 build 176 as we speak, I'll report back on stability in a day or two!

That firmware updater was reeeeeally easy. Wouldn't work on Linux unfortunately even through Chromium but worked like a dream in Windows.

droans commented 7 months ago

It's been about eight hours so far and no issues... Usually by now it would have crashed. I'll keep it running and update tomorrow.

Nerivec commented 7 months ago

@Koenkk Flagging this in case you're not subscribed anymore, since release day is approaching and you'll probably do some housekeeping... Seems there might indeed be some problem related to Alpine, @droans is reporting better behavior from building Z2M 1.35.1 with Alpine 3.18.4 instead of 3.18.5...

droans commented 7 months ago

@Nerivec

Unfortunately it crashed again this morning, surprisingly lasting about 18 hours.

Interestingly, the dmesg errors and the Herdsman errors were slightly out of sync. The dmesg errors first start at 4:13:50. Herdsman reports a wait success at 4:13:45 followed by a watchdog wait at 4:13:55 and a failure two seconds later.

My guess at this point is that it's possibly due to a dependency change or maybe even a device converter? I'm not confident on it being a dependency, though... I looked through the changes about a week ago and didn't see any that would affect the operation; they all seemed to be related to the linter or utility.

I do have an "odd" network so maybe that? My old coordinator, a TI LAUNCHXL, is being used as a router so I suppose it could be causing issues. I also used to have some problems with my Ikea outlets dropping off with the SkyConnect but I haven't seen that occur in months.

I also used the lsusb suggestion but it doesn't seem like I can get power reporting from it, though; the closest I see is max power which is always reporting 100mA.

Would you have any suggestions on how I can help diagnose this further? I've got backups of my data so I'm not worried if there's a risk of destroying my data. I can also provide reasonable access to my instance if needed.

I'll upload new logs in a couple hours.

droans commented 7 months ago

New logs...

Z2M

Filtered Syslog

Oddly, Z2M worked perfectly fine from when I started yesterday until it restarted at 3:30 AM due to HA restarting. At that point, it worked for about 45 minutes until it went down.

I couldn't find anything in related logs that seems relevant... No HA or MQTT issues, no unexpected Docker logs, etc.

I rebuilt my container using zigbee-herdsman-converters 15.130.1. We'll see if that makes a difference. If not, my next steps would be to rebuild it with zigbee-herdsman 0.25.

Nerivec commented 7 months ago

Thanks for the detailed report. Unfortunately, like you mentioned, I didn't find anything relevant in the logs... There's a ~45min gap at the beginning of your syslog though, seems strange..? You wouldn't have the RAM usage pre-crash by any chance? Same question as above, what firmware "supplier" are you using for the skyconnect (Nabu, darkxst, etc)? You could try to re-flash, even same version, just in case something weird is going on... Another thing you can check, the configuration.yaml file (directly, not via config UI)... to make sure it wasn't somehow duplicated (the folder), or improperly saved by the UI.

Possibly https://github.com/Koenkk/zigbee-herdsman/pull/897 will help.

Error 71 should be -EPROTO, but that's not very helpful...

Ref: https://github.com/torvalds/linux/blob/861c0981648f5b64c86fd028ee622096eb7af05a/drivers/usb/serial/cp210x.c

Koenkk commented 7 months ago

@Nerivec downgraded to 3.18.4 just in case

droans commented 7 months ago

There's a ~45min gap at the beginning of your syslog though, seems strange..?

I left that in the syslog intentionally in case you thought it could be relevant. It's from when Docker started the container up.

You wouldn't have the RAM usage pre-crash by any chance?

I actually do! Unfortunately, it doesn't seem to show any issues. None of my other hardware data show anything unusual either...

image

Same question as above, what firmware "supplier" are you using for the skyconnect (Nabu, darkxst, etc)? You could try to re-flash, even same version, just in case something weird is going on...

I installed it using the Nabu Casa online flasher. I can give that a try if my other attempts don't help.

Another thing you can check, the configuration.yaml file (directly, not via config UI)... to make sure it wasn't somehow duplicated (the folder), or improperly saved by the UI.

It doesn't seem like I do.

image

Possibly https://github.com/Koenkk/zigbee-herdsman/pull/897 will help.

Thanks - will try it out next.

Nerivec commented 7 months ago

I left that in the syslog intentionally in case you thought it could be relevant. It's from when Docker started the container up.

So there's no other error (possibly more descriptive) before Jan 30 04:13:50 server kernel: [1955564.471364] usb 1-3.3: clear tt 1 (9042) error -71?

It doesn't seem like I do.

And the yaml inside is correct I assume?

droans commented 7 months ago

Unfortunately, no... The previous recent logs were just Docker handling networks and containers.

And the yaml inside is correct I assume?

I assume so. I haven't made any changes to the config since I opened the issue.

Nerivec commented 7 months ago

I assume so. I haven't made any changes to the config since I opened the issue.

I ask because I had a case recently (after an update), where the config edited via UI was not properly saved to the yaml file (for some reason...); it created a completely messed up starting point for Z2M. But assuming your initial post was of the config "post-update", it seems okay...

droans commented 7 months ago

Well, good news... I rebuilt it with zigbee-herdsman 0.25 and it has been working fine for over 24 hours now.

I'm going to try bumping forward the version until it crashes again.

Nerivec commented 7 months ago

Thanks for the patience. 😉

Eliminating what was already tested, I see two changes from 0.25>0.30 worth mentioning, the typescript compiler version (went from ES2018 to ES2022, in 0.29), and the request queue cleanup (0.26). I'd go for these two points in time first; hopefully you'll have results faster.

@slugzero Mind checking the below two points that changed (or anything else I might have missed, we're looking for anything that could result in over-use of memory, or flooding of the adapter -anything that could crash it basically, even a remote possibility-), since you did the PRs, you're familiar with the code there:

https://github.com/Koenkk/zigbee-herdsman/blob/59c1bbe2d090403c0443f97d4fba3e644b1121f3/src/controller/model/endpoint.ts#L273 vs https://github.com/Koenkk/zigbee-herdsman/blob/189c921fc3ba63591789ee225dd37134d00bc54d/src/controller/helpers/requestQueue.ts#L32

https://github.com/Koenkk/zigbee-herdsman/blob/59c1bbe2d090403c0443f97d4fba3e644b1121f3/src/controller/model/endpoint.ts#L304 vs https://github.com/Koenkk/zigbee-herdsman/blob/189c921fc3ba63591789ee225dd37134d00bc54d/src/controller/helpers/requestQueue.ts#L58

slugzero commented 7 months ago

@Nerivec I had a look at the logs but did not find anything that would hint to the request queue. In log.1.txt, there is a single message being queued (line 21546), but this is at 10:59, and the errors occur already at 9:14.

What puzzles me are the 'No such file or directory' errors. Looks like the port was not properly closed or some other process is blocking it. What does lsof |grep /dev/serial output after this error occurs? I think it should be empty (because port is closed according to the log, line 16213), but I guess that node.js is still holding the port open

droans commented 7 months ago

What puzzles me are the 'No such file or directory' errors. Looks like the port was not properly closed or some other process is blocking it. What does lsof |grep /dev/serial output after this error occurs?

Unfortunately I've already restarted the container by the time I think about checking.

My current thought is that it's due to how Docker handles device mappings. Based on this post and a few others I've read, Docker won't reconnect devices after they are unplugged and plugged back in. Same goes for mapped volumes. I believe I can work around this by either using device_cgroup_rules or removing the device mapping and changing the volume to just /dev:/dev.

Nerivec commented 7 months ago

Thanks @slugzero!

It starts with an I/O error first though, and from then, the port gets lock I figured. I/O (usually?) points to the baudrate, but since it's working for a while, I don't see why suddenly it wouldn't like one of the serial settings.

I pushed a few PRs (in latest release) to handle the init/reset logic for EZSP better (few code paths that didn't end properly), it should now be smoother, hopefully, but the weird thing is the old code would affect 0.25 just as much 0.30...

Definitely try with today's new release though, if it fails again, at least the logs should be clearer.

Long shot... you don't have anything that could change the default version of node installed by Alpine in your container, do you? It should still be v18. The serialport package was having issues not long ago with recent node versions (> 20.2)...

newlund commented 7 months ago

I had a lot of problems starting zigbee2mqtt with my skyconnect (fw 7.3.2.0 build 212). Now I disabled RTS / CTS and it works like a charm every time. "rtscts": false

Nerivec commented 7 months ago

@newlund Did you try rtscts again with latest release? I changed the settings a bit, it previously was using both software + hardware flow control, now if hardware is enabled (rtscts), it won't enable xon/xoff.

droans commented 7 months ago

Looks like a lot of improvements should at least improve logging...

I've had 0.28.0 working for close to 24 hours now, too. I'm going to just switch to 1.35.2 and wait for it to give me errors. If the logs aren't helpful, I'll test out herdsman 0.29/0.30.

newlund commented 7 months ago

@newlund Did you try rtscts again with latest release? I changed the settings a bit, it previously was using both software + hardware flow control, now if hardware is enabled (rtscts), it won't enable xon/xoff.

Yes, it was after the latest release (1.35.2) I tried to disable rtscts. Had the problems with the previous release as well but didn't try it with that version.

newlund commented 7 months ago

Now I enabled rtscts again and immediately when starting Z2M I got the error again:

debug 2024-02-02 16:48:41: Loaded state from file /config/zigbee2mqtt/state.json info 2024-02-02 16:48:41: Logging to console and directory: '/config/zigbee2mqtt/log/2024-02-02.16-48-41' filename: log.txt info 2024-02-02 16:48:41: Starting Zigbee2MQTT version 1.35.2 (commit #unknown) info 2024-02-02 16:48:41: Starting zigbee-herdsman (0.33.5) debug 2024-02-02 16:48:41: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backupPath":"/config/zigbee2mqtt/coordinator_backup.json","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","databasePath":"/config/zigbee2mqtt/database.db","network":{"channelList":[20],"extendedPanID":[221,221,221,221,221,221,221,221],"networkKey":"HIDDEN","panID":6754},"serialPort":{"adapter":"ezsp","baudRate":115200,"path":"/dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_c8ec6f61dd93ed1181f07ff23b20a988-if00-port0","rtscts":true}}' error 2024-02-02 16:48:55: Error while starting zigbee-herdsman error 2024-02-02 16:48:55: Failed to start zigbee error 2024-02-02 16:48:55: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions error 2024-02-02 16:48:55: Exiting... error 2024-02-02 16:48:55: 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:106:27) at start (/app/index.js:107:5)

Disabling rtscts makes it work again.

newlund commented 7 months ago

Strange, I enabled zigbee-herdsman debug logging but it does not end up in ../config/zigbee2mqtt/log/ Where can I find it?

Nerivec commented 7 months ago

In the logs tab of Z2M. https://www.zigbee2mqtt.io/guide/usage/debug.html#zigbee-herdsman-debug-logging

What firmware supplier are you using (Nabu Casa, darkxst, other...)?

droans commented 7 months ago

Sorry for the delay here - I've been busy this weekend.

I've been running 1.35.2 and haven't seen a single issue yet. I'm guessing the RTS/CTS change might have fixed it?

If it occurs again, I'll grab the logs. Thanks for your help!

Nerivec commented 7 months ago

Thanks for the feedback! Likely it was messing with the device yes, though it was the same with earlier versions... I'm going through my list of fixes one by one, next release should have a lot of them... Hopefully the overall stability will benefit eventually, even if it often messes with a couple of setups, temporarily (too many possible configurations, one or two always have to break...).

PS: @droans, if you don't mind, and have time, I might ping you from time to time if I find myself in need of data from a different setup (yours is very different from mine, and you have lots of data 😉).

newlund commented 7 months ago

Here is the zigbee-herdsman debug log when I have rtscts enabled. If I disable rtscts it starts up normally without errors.

[18:45:00] INFO: Preparing to start... [18:45:00] INFO: Socat not enabled [18:45:00] INFO: Zigbee Herdsman debug logging enabled [18:45:01] INFO: Starting Zigbee2MQTT... Zigbee2MQTT:debug 2024-02-05 18:45:05: Loaded state from file /config/zigbee2mqtt/state.json Zigbee2MQTT:info 2024-02-05 18:45:05: Logging to console and directory: '/config/zigbee2mqtt/log/2024-02-05.18-45-05' filename: log.txt Zigbee2MQTT:info 2024-02-05 18:45:05: Starting Zigbee2MQTT version 1.35.2 (commit #unknown) Zigbee2MQTT:info 2024-02-05 18:45:05: Starting zigbee-herdsman (0.33.5) Zigbee2MQTT:debug 2024-02-05 18:45:05: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backupPath":"/config/zigbee2mqtt/coordinator_backup.json","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","databasePath":"/config/zigbee2mqtt/database.db","network":{"channelList":[20],"extendedPanID":[221,221,221,221,221,221,221,221],"networkKey":"HIDDEN","panID":6754},"serialPort":{"adapter":"ezsp","baudRate":115200,"path":"/dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_c8ec6f61dd93ed1181f07ff23b20a988-if00-port0","rtscts":true}}' 2024-02-05T17:45:05.585Z zigbee-herdsman:adapter Failed to validate path: 'Error: spawn udevadm ENOENT' 2024-02-05T17:45:05.586Z zigbee-herdsman:adapter:ezsp:debg Adapter concurrent: 8 2024-02-05T17:45:05.587Z zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[1,3,5,7,9,11,7,15,0,2,7,4,8,7,4,13],"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[20]},"serialPort":{"baudRate":115200,"rtscts":true,"path":"/dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_c8ec6f61dd93ed1181f07ff23b20a988-if00-port0","adapter":"ezsp"},"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-05T17:45:05.590Z zigbee-herdsman:adapter:ezsp:uart Opening SerialPort with {"path":"/dev/serial/by-id/usb-Nabu_Casa_SkyConnect_v1.0_c8ec6f61dd93ed1181f07ff23b20a988-if00-port0","baudRate":115200,"rtscts":true,"autoOpen":false,"parity":"none","stopBits":1,"xon":false,"xoff":false} 2024-02-05T17:45:05.616Z zigbee-herdsman:adapter:ezsp:uart Serialport opened 2024-02-05T17:45:05.616Z zigbee-herdsman:adapter:ezsp:uart Uart reseting 2024-02-05T17:45:05.617Z zigbee-herdsman:adapter:ezsp:uart --> Write reset 2024-02-05T17:45:05.618Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e] 2024-02-05T17:45:05.620Z zigbee-herdsman:adapter:ezsp:uart -?- waiting reset 2024-02-05T17:45:05.622Z zigbee-herdsman:adapter:ezsp:uart <-- [c20203d20a7e] 2024-02-05T17:45:05.623Z zigbee-herdsman:adapter:ezsp:uart --> parsed c20203d20a7e 2024-02-05T17:45:05.623Z zigbee-herdsman:adapter:ezsp:uart <-- Error c20203d20a7e 2024-02-05T17:45:05.623Z zigbee-herdsman:adapter:ezsp:uart Uart reseting 2024-02-05T17:45:05.624Z zigbee-herdsman:adapter:ezsp:uart --> Write reset 2024-02-05T17:45:05.624Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e] 2024-02-05T17:45:05.625Z zigbee-herdsman:adapter:ezsp:uart -?- waiting reset 2024-02-05T17:45:06.724Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527e] 2024-02-05T17:45:06.725Z zigbee-herdsman:adapter:ezsp:uart --> parsed c1020b0a527e 2024-02-05T17:45:06.725Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK c1020b0a527e 2024-02-05T17:45:06.725Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e 2024-02-05T17:45:06.726Z zigbee-herdsman:adapter:ezsp:uart -+- waiting reset success 2024-02-05T17:45:06.726Z zigbee-herdsman:adapter:ezsp:uart -+- waiting reset success 2024-02-05T17:45:06.727Z zigbee-herdsman:adapter:ezsp:ezsp ==> version: {"desiredProtocolVersion":4} 2024-02-05T17:45:06.728Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"cls":"version","id":0,"isRequest":true,"desiredProtocolVersion":4} 2024-02-05T17:45:06.729Z zigbee-herdsman:adapter:ezsp:uart --> DATA (0,0,0): 00000004 2024-02-05T17:45:06.730Z zigbee-herdsman:adapter:ezsp:uart --> [004221a850ed2c7e] 2024-02-05T17:45:06.730Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (1) 2024-02-05T17:45:07.827Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527e0142a1a8582835c1abb17e] 2024-02-05T17:45:07.828Z zigbee-herdsman:adapter:ezsp:uart --> parsed c1020b0a527e 2024-02-05T17:45:07.828Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK c1020b0a527e 2024-02-05T17:45:07.828Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e 2024-02-05T17:45:07.829Z zigbee-herdsman:adapter:ezsp:uart --> parsed 0142a1a8582835c1abb17e 2024-02-05T17:45:07.829Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (0,1,0): 0142a1a8582835c1abb17e 2024-02-05T17:45:07.829Z zigbee-herdsman:adapter:ezsp:uart --> ACK (1) 2024-02-05T17:45:07.830Z zigbee-herdsman:adapter:ezsp:uart --> [8160597e] 2024-02-05T17:45:07.830Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (1): 0142a1a8582835c1abb17e 2024-02-05T17:45:07.831Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: 0080000c022073 2024-02-05T17:45:07.832Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x0: {"cls":"version","id":0,"isRequest":false,"protocolVersion":12,"stackType":2,"stackVersion":29472} 2024-02-05T17:45:07.832Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (1) success 2024-02-05T17:45:07.832Z zigbee-herdsman:adapter:ezsp:ezsp Switching to eszp version 12 2024-02-05T17:45:07.833Z zigbee-herdsman:adapter:ezsp:ezsp ==> version: {"desiredProtocolVersion":12} 2024-02-05T17:45:07.833Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"cls":"version","id":0,"isRequest":true,"desiredProtocolVersion":12} 2024-02-05T17:45:07.834Z zigbee-herdsman:adapter:ezsp:uart --> DATA (0,1,0): 01000100000c 2024-02-05T17:45:07.834Z zigbee-herdsman:adapter:ezsp:uart --> [014321a9542a19be807e] 2024-02-05T17:45:07.834Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (1) 2024-02-05T17:45:07.841Z zigbee-herdsman:adapter:ezsp:uart <-- [a1443b7e] 2024-02-05T17:45:07.841Z zigbee-herdsman:adapter:ezsp:uart --> parsed a1443b7e 2024-02-05T17:45:07.842Z zigbee-herdsman:adapter:ezsp:uart <-- NAK (1): a1443b7e 2024-02-05T17:45:07.843Z zigbee-herdsman:adapter:ezsp:uart NAK Expected packet sequence 1 2024-02-05T17:45:07.843Z zigbee-herdsman:adapter:ezsp:uart --> Error: Error: Recv NAK frame 2024-02-05T17:45:07.843Z zigbee-herdsman:adapter:ezsp:uart -!- break waiting (1) 2024-02-05T17:45:07.843Z zigbee-herdsman:adapter:ezsp:uart Can't send DATA frame (0,1,0): 01000100000c 2024-02-05T17:45:08.347Z zigbee-herdsman:adapter:ezsp:uart ->> DATA (0,1,1): 01000100000c 2024-02-05T17:45:08.347Z zigbee-herdsman:adapter:ezsp:uart --> [094321a9542a192d2d7e] 2024-02-05T17:45:08.348Z zigbee-herdsman:adapter:ezsp:uart -?- rewaiting (1) 2024-02-05T17:45:08.353Z zigbee-herdsman:adapter:ezsp:uart <-- [8160597e] 2024-02-05T17:45:08.353Z zigbee-herdsman:adapter:ezsp:uart --> parsed 8160597e 2024-02-05T17:45:08.354Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (1): 8160597e 2024-02-05T17:45:08.354Z zigbee-herdsman:adapter:ezsp:uart -+- rewaiting (1) success 2024-02-05T17:45:16.731Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0 2024-02-05T17:45:16.731Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null 2024-02-05T17:45:18.356Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"cls":"nop","id":5,"isRequest":true} 2024-02-05T17:45:18.358Z zigbee-herdsman:adapter:ezsp:uart --> DATA (1,1,0): 0200010500 2024-02-05T17:45:18.358Z zigbee-herdsman:adapter:ezsp:uart --> [7d314021a9512a9a0d7e] 2024-02-05T17:45:18.359Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (2) Zigbee2MQTT:error 2024-02-05 18:45:18: Error while starting zigbee-herdsman Zigbee2MQTT:error 2024-02-05 18:45:18: Failed to start zigbee Zigbee2MQTT:error 2024-02-05 18:45:18: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions Zigbee2MQTT:error 2024-02-05 18:45:18: Exiting... Zigbee2MQTT:error 2024-02-05 18:45:18: 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:106:27) at start (/app/index.js:107:5)

Nerivec commented 7 months ago

It's definitely receiving messed up frames.

What firmware supplier are you using?

newlund commented 7 months ago

I have tried different usb extension cables now and also tried a different usb port on my nuc. But still the same with rtscts enabled.

I'm using 7.3.2.0 from here https://github.com/NabuCasa/silabs-firmware Updated using SL Web tools https://skyconnect.home-assistant.io/firmware-update/

Could it be any usb setting in bios causing the problem? Should I try to update firmware to the latest (7.4.0.0)

Nerivec commented 6 months ago

@newlund Sorry, missed your message somehow... There seems to be inconsistencies with the rtscts setting and the SkyConnect... I've seen several reports that indicate it works better without it... I guess you are not alone 😄 I'd stay on 7.3.x for a while longer. 7.4 will be nice (a couple of nice features in there) but only once ember is properly tested and out of "experimental stage" 😉

newlund commented 6 months ago

My issue with having rtscts enabled seems solved now in z2M v1.36.0 Still running skyconnect FW 7.3.2.0

Thank you! :)

github-actions[bot] commented 1 week ago

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