Koenkk / zigbee2mqtt

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

HAOS Addon 1.30.2-1 broken for ezsp #16908

Closed rosti76 closed 1 year ago

rosti76 commented 1 year ago

What happened?

After update to 1.30.2-1 Z2M starting, connects to configured Adapter, but fails to establish right protocol.

Skyconnect usb stick is connected with SiliconLabs Multiprotocol. Z2M connects to. port: tcp://core-silabs-multiprotocol:9999 adapter: ezsp

was working with previous version of Z2M

What did you expect to happen?

Z2M connects successfully as in previous verion

How to reproduce it (minimal and precise)

install 1.30.2-1, connect to SL Multiprotocol

Zigbee2MQTT version

1.30.2

Adapter firmware version

SLMultiprotocol 1.0.0

Adapter

Skyconnect+SL Multiprotocol

Debug log

[09:11:13] INFO: Preparing to start... [09:11:13] INFO: Socat not enabled [09:11:13] INFO: Zigbee Herdsman debug logging enabled [09:11:13] INFO: Starting Zigbee2MQTT... Zigbee2MQTT:debug 2023-03-04 09:11:14: Loaded state from file /config/zigbee2mqtt/state.json Zigbee2MQTT:info 2023-03-04 09:11:14: Logging to console and directory: '/config/zigbee2mqtt/log/2023-03-04.09-11-14' filename: log.txt Zigbee2MQTT:debug 2023-03-04 09:11:14: Removing old log directory '/config/zigbee2mqtt/log/2023-03-04.09-03-32' Zigbee2MQTT:info 2023-03-04 09:11:14: Starting Zigbee2MQTT version 1.30.2 (commit #unknown) Zigbee2MQTT:info 2023-03-04 09:11:14: Starting zigbee-herdsman (0.14.96) Zigbee2MQTT:debug 2023-03-04 09:11:14: 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":[11],"extendedPanID":[221,221,221,221,221,221,221,221],"networkKey":"HIDDEN","panID":6754},"serialPort":{"adapter":"ezsp","path":"tcp://core-silabs-multiprotocol:9999"}}' 2023-03-04T08:11:14.495Z 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://core-silabs-multiprotocol:9999","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}}' 2023-03-04T08:11:14.495Z zigbee-herdsman:adapter:ezsp:uart Opening TCP socket with core-silabs-multiprotocol:9999 2023-03-04T08:11:14.499Z zigbee-herdsman:adapter:ezsp:uart Socket connected 2023-03-04T08:11:14.499Z zigbee-herdsman:adapter:ezsp:uart Socket ready 2023-03-04T08:11:14.499Z zigbee-herdsman:adapter:ezsp:uart Uart reseting 2023-03-04T08:11:14.499Z zigbee-herdsman:adapter:ezsp:uart --> Write reset 2023-03-04T08:11:14.500Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e] 2023-03-04T08:11:14.500Z zigbee-herdsman:adapter:ezsp:uart -?- waiting reset 2023-03-04T08:11:14.897Z zigbee-herdsman:adapter:ezsp:uart <-- [] 2023-03-04T08:11:14.898Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527e] 2023-03-04T08:11:14.898Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK: c1020b0a527e 2023-03-04T08:11:14.898Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e 2023-03-04T08:11:14.899Z zigbee-herdsman:adapter:ezsp:uart -+- waiting reset success 2023-03-04T08:11:14.899Z zigbee-herdsman:adapter:ezsp:ezsp ==> version: {"desiredProtocolVersion":4} 2023-03-04T08:11:14.899Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"cls":"version","id":0,"isRequest":true,"desiredProtocolVersion":4} 2023-03-04T08:11:14.899Z zigbee-herdsman:adapter:ezsp:uart --> DATA (0,0,0): 00000004 2023-03-04T08:11:14.900Z zigbee-herdsman:adapter:ezsp:uart --> [004221a850ed2c7e] 2023-03-04T08:11:14.900Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (1) 2023-03-04T08:11:16.900Z zigbee-herdsman:adapter:ezsp:uart --> Error: Error: {"sequence":1} after 2000ms 2023-03-04T08:11:16.900Z zigbee-herdsman:adapter:ezsp:uart -!- break waiting (1) 2023-03-04T08:11:16.900Z zigbee-herdsman:adapter:ezsp:uart Can't send DATA frame (0,0,0): 00000004 2023-03-04T08:11:17.401Z zigbee-herdsman:adapter:ezsp:uart ->> DATA (0,0,1): 00000004 2023-03-04T08:11:17.401Z zigbee-herdsman:adapter:ezsp:uart --> [084221a850ef017e] 2023-03-04T08:11:17.401Z zigbee-herdsman:adapter:ezsp:uart -?- rewaiting (1) 2023-03-04T08:11:19.139Z zigbee-herdsman:adapter:ezsp:uart <-- [] 2023-03-04T08:11:19.139Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527e] 2023-03-04T08:11:19.139Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK: c1020b0a527e 2023-03-04T08:11:19.139Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e 2023-03-04T08:11:19.140Z zigbee-herdsman:adapter:ezsp:uart <-- [01] 2023-03-04T08:11:19.140Z zigbee-herdsman:adapter:ezsp:uart <-- [42a1a85e2805c0999c7e] 2023-03-04T08:11:19.140Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (0,1,0): 0142a1a85e2805c0999c7e 2023-03-04T08:11:19.141Z zigbee-herdsman:adapter:ezsp:uart --> ACK (1) 2023-03-04T08:11:19.141Z zigbee-herdsman:adapter:ezsp:uart --> [8160597e] 2023-03-04T08:11:19.141Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: 0080000a021072 2023-03-04T08:11:19.141Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x0: {"cls":"version","id":0,"isRequest":false,"protocolVersion":10,"stackType":2,"stackVersion":29200} 2023-03-04T08:11:19.141Z zigbee-herdsman:adapter:ezsp:uart -+- rewaiting (1) success 2023-03-04T08:11:19.141Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (1) success 2023-03-04T08:11:19.141Z zigbee-herdsman:adapter:ezsp:ezsp Switching to eszp version 10 2023-03-04T08:11:19.141Z zigbee-herdsman:adapter:ezsp:ezsp ==> version: {"desiredProtocolVersion":10} 2023-03-04T08:11:19.141Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"cls":"version","id":0,"isRequest":true,"desiredProtocolVersion":10} 2023-03-04T08:11:19.142Z zigbee-herdsman:adapter:ezsp:uart --> DATA (0,1,0): 01000100000a 2023-03-04T08:11:19.142Z zigbee-herdsman:adapter:ezsp:uart --> [014321a9542a1fde467e] 2023-03-04T08:11:19.142Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (1) 2023-03-04T08:11:19.142Z zigbee-herdsman:adapter:ezsp:uart <-- [8160597e] 2023-03-04T08:11:19.142Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (1): 8160597e 2023-03-04T08:11:19.142Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (1) success 2023-03-04T08:11:20.140Z zigbee-herdsman:adapter:ezsp:uart <-- [a1443b7e] 2023-03-04T08:11:20.140Z zigbee-herdsman:adapter:ezsp:uart <-- NAK (1): a1443b7e 2023-03-04T08:11:20.141Z zigbee-herdsman:adapter:ezsp:uart NAK Unexpected packet sequence 1 2023-03-04T08:11:24.901Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0 2023-03-04T08:11:24.901Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null 2023-03-04T08:11:29.146Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"cls":"nop","id":5,"isRequest":true} 2023-03-04T08:11:29.147Z zigbee-herdsman:adapter:ezsp:uart --> DATA (1,1,0): 0200010500 2023-03-04T08:11:29.147Z zigbee-herdsman:adapter:ezsp:uart --> [7d314021a9512a9a0d7e] 2023-03-04T08:11:29.147Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (2) Zigbee2MQTT:error 2023-03-04 09:11:29: Error while starting zigbee-herdsman Zigbee2MQTT:error 2023-03-04 09:11:29: Failed to start zigbee Zigbee2MQTT:error 2023-03-04 09:11:29: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions Zigbee2MQTT:error 2023-03-04 09:11:29: Exiting... Zigbee2MQTT:error 2023-03-04 09:11:29: Error: Failure send version:{"type":"Buffer","data":[1,0,1,0,0,10]} at /app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/ezsp.ts:551:23 at Queue.executeNext (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:32:32) 2023-03-04T08:11:29.167Z zigbee-herdsman:adapter:ezsp:uart <-- [1240a1a90c2a25bdf97e] 2023-03-04T08:11:29.167Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (1,2,0): 1240a1a90c2a25bdf97e 2023-03-04T08:11:29.168Z zigbee-herdsman:adapter:ezsp:uart --> ACK (2) 2023-03-04T08:11:29.168Z zigbee-herdsman:adapter:ezsp:uart --> [82503a7e] 2023-03-04T08:11:29.168Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: 028001580030 2023-03-04T08:11:29.168Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x58: {"cls":"invalidCommand","id":88,"isRequest":false,"reason":48} 2023-03-04T08:11:29.168Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (2) success

kirovilya commented 1 year ago

Make sure you have disabled ZHA, which may also be trying to connect to this port. Also check that the stick is not connected to USB3. Looking at logs - a problem of connection by port.

rosti76 commented 1 year ago

Zha not installed at all, nothing changed on USB stick connection which was working before. Z2M is connecting to Silicon Labs Multiprotocol (which has not changed) and not to USB stick directly.

jhbruhn commented 1 year ago

I can confirm this happening on todays Z2M Edge addon version as well.

tommyjlong commented 1 year ago

I have the same problem and I'll add my posting as a cross reference https://github.com/zigbee2mqtt/hassio-zigbee2mqtt/issues/469 to this one. In my posting I show a working log using 1.30.1 and the non-working log using 1.30.2

kirovilya commented 1 year ago

strange behavior during initialization. Perhaps we need to increase the response timeout when sending a reset. but I have no way to test this assumption - I don't have a SkyConnect stick.

who can check? in file /zigbee-herdsman/dist/adapter/ezsp/driver/uart.js (line 277): in reset() was: const waiter = this.waitFor(-1).start(); change to: const waiter = this.waitFor(-1, 10000).start();

rosti76 commented 1 year ago

Could do this, but not sure how - have HAOS 9.5 with official Z2M Addon which is failing to start at the moment because of this issue.

FredWst commented 1 year ago

hi, I've same issue.

@kirovilya maybe you could push this "test patch" on edge to check if ok ? I don't know how to check that on HAOS 9.5

Fred

DavidArthur2 commented 1 year ago

A similar issue here. Out of nowhere yesterday Z2M stopped, and could not restart it. Socket connection error.

MattWestb commented 1 year ago

The Zigbeed demon is little lazy and if not getting the connection OK or connection is being lost it can restarting and Z2M cant connecting OK until it have restarted OK that taking little time. I think the PR made shall helping getting it working OK as it was before. ZHA have also having problems with connections after restart but most is fixed after little debugging and patching.

Great that also Z2M user have getting Open Thread Boarder Routers and Zigbee working on there dongles !!

PS: EVE Energy and Nanoleaf lights is flash fast and stable then connecting them with HomeKit client in HA over thread and is having all functions the devices have (Matter firmware dont have all advance functions). :-)))

DavidArthur2 commented 1 year ago

Is this in hassio root folder, or where? I could check it

FredWst commented 1 year ago

Hi,

I try with last edge push about one hour ago and works for me.

Fred

fanek007 commented 1 year ago

Hi,

I edited the file and it works.

Thanks, Fanek

tommyjlong commented 1 year ago

I just tried out the Edge push as well. It does work!! (As an FYI, for me it took a couple of tries, because multiprotocol's zigbeed seems to crash the first time around).

espenfjo commented 1 year ago

This did not work for me, but physically unplugging/replugging the USB device worked. Rebooting or anything else I did before the replug did anything to alleviate the issue.

tommyjlong commented 1 year ago

As an FYI, I just tried out the 1.30.3-1 release, and even though I didn't see this issue nor the pull request-678 listed in the changelog, this release does seem to work.

github-actions[bot] commented 1 year 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