search

Koenkk / zigbee2mqtt

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

New Edge not starting anymore with ezsp 7.4.0 #20827

Closed wastez closed 2 months ago

wastez commented 9 months ago

What happened?

It doesn’t start anymore. no error message, just writing „starting“ in the logs. the gui doesn’t get available.

What did you expect to happen?

No response

How to reproduce it (minimal and precise)

No response

Zigbee2MQTT version

latest edge

Adapter firmware version

7.4.0

Adapter

EZSP Sonoff Dongle E

Setup

Proxmox

Debug log

No response

RichardPar commented 9 months ago

Can you check the logs of the silabs addon? You might find some more information there... Something seems to make the socket drop in some weird fashion.

I'll dig for some more debug.. Silabs is listening

Z2MQTT looks like its connecting to something.. (below is the same small logs from Silabs Multiprotocol) 

[21:16:06] INFO: Socat enabled
[21:16:07] INFO: Starting socat
Socat startup parameters:
Options:     -d -d
Master:      pty,raw,echo=0,link=/tmp/ttyZ2M,mode=777
Slave:       tcp-listen:8485,keepalive,nodelay,reuseaddr,keepidle=1,keepintvl=1,keepcnt=5
[21:16:07] INFO: Starting socat process ...
2024/01/23 21:16:07 socat[47] N PTY is /dev/pts/0
2024/01/23 21:16:07 socat[47] N listening on AF=2 0.0.0.0:8485
[21:16:08] INFO: Zigbee Herdsman debug logging enabled
[21:16:11] INFO: Starting Zigbee2MQTT...
Zigbee2MQTT:debug 2024-01-23 21:16:23: Loaded state from file /config/zigbee2mqtt/state.json
Zigbee2MQTT:info  2024-01-23 21:16:23: Logging to console and directory: '/config/zigbee2mqtt/log/2024-01-23.21-16-22' filename: log.txt
Zigbee2MQTT:debug 2024-01-23 21:16:23: Removing old log directory '/config/zigbee2mqtt/log/2024-01-23.17-45-09'
Zigbee2MQTT:info  2024-01-23 21:16:23: Starting Zigbee2MQTT version 1.35.1-dev (commit #de7bc7c)
Zigbee2MQTT:info  2024-01-23 21:16:23: Starting zigbee-herdsman (0.32.7)
Zigbee2MQTT:debug 2024-01-23 21:16:23: 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":[79,21,20,244,142,185,35,167],"networkKey":"HIDDEN","panID":57138},"serialPort":{"adapter":"ezsp","path":"tcp://core-silabs-multiprotocol:9999","rtscts":false}}'
2024-01-23T21:16:23.529Z zigbee-herdsman:adapter:ezsp:debg Adapter concurrent: 8
2024-01-23T21:16:23.531Z zigbee-herdsman:controller:log Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[189,75,78,133,143,84,44,153,64,153,244,26,19,43,146,35],"panID":57138,"extendedPanID":[79,21,20,244,142,185,35,167],"channelList":[11]},"serialPort":{"rtscts":false,"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}}'
2024-01-23T21:16:23.534Z zigbee-herdsman:adapter:ezsp:uart Opening TCP socket with core-silabs-multiprotocol:9999
2024-01-23T21:16:23.554Z zigbee-herdsman:adapter:ezsp:uart Socket connected
2024-01-23T21:16:23.555Z zigbee-herdsman:adapter:ezsp:uart Socket ready
2024-01-23T21:16:23.556Z zigbee-herdsman:adapter:ezsp:uart Uart reseting
2024-01-23T21:16:23.558Z zigbee-herdsman:adapter:ezsp:uart --> Write reset
2024-01-23T21:16:23.560Z zigbee-herdsman:adapter:ezsp:uart --> [1ac038bc7e]
2024-01-23T21:16:23.561Z zigbee-herdsman:adapter:ezsp:uart -?- waiting reset
2024-01-23T21:16:23.566Z zigbee-herdsman:adapter:ezsp:uart <-- [c1020b0a527e]
2024-01-23T21:16:23.568Z zigbee-herdsman:adapter:ezsp:uart --> parsed c1020b0a527e
2024-01-23T21:16:23.569Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK c1020b0a527e
2024-01-23T21:16:23.570Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e
2024-01-23T21:16:23.572Z zigbee-herdsman:adapter:ezsp:uart -+- waiting reset success
2024-01-23T21:16:23.573Z zigbee-herdsman:adapter:ezsp:ezsp ==> version: {"desiredProtocolVersion":4}
2024-01-23T21:16:23.574Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"version","_id_":0,"_isRequest_":true,"desiredProtocolVersion":4}
2024-01-23T21:16:23.577Z zigbee-herdsman:adapter:ezsp:uart --> DATA (0,0,0): 00000004
2024-01-23T21:16:23.578Z zigbee-herdsman:adapter:ezsp:uart --> [004221a850ed2c7e]
2024-01-23T21:16:23.579Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (1)
2024-01-23T21:16:25.582Z zigbee-herdsman:adapter:ezsp:uart --> Error: Error: {"sequence":1} after 2000ms
2024-01-23T21:16:25.582Z zigbee-herdsman:adapter:ezsp:uart -!- break waiting (1)
2024-01-23T21:16:25.582Z zigbee-herdsman:adapter:ezsp:uart Can't send DATA frame (0,0,0): 00000004
2024-01-23T21:16:26.084Z zigbee-herdsman:adapter:ezsp:uart ->> DATA (0,0,1): 00000004
2024-01-23T21:16:26.084Z zigbee-herdsman:adapter:ezsp:uart --> [084221a850ef017e]
2024-01-23T21:16:26.085Z zigbee-herdsman:adapter:ezsp:uart -?- rewaiting (1)
2024-01-23T21:16:27.649Z zigbee-herdsman:adapter:ezsp:uart <-- [c102]
2024-01-23T21:16:27.650Z zigbee-herdsman:adapter:ezsp:uart <-- [0b0a527e0142a1a8592815c6ab047e]
2024-01-23T21:16:27.650Z zigbee-herdsman:adapter:ezsp:uart --> parsed c1020b0a527e
2024-01-23T21:16:27.652Z zigbee-herdsman:adapter:ezsp:uart <-- RSTACK c1020b0a527e
2024-01-23T21:16:27.652Z zigbee-herdsman:adapter:ezsp:uart RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e
2024-01-23T21:16:27.652Z zigbee-herdsman:adapter:ezsp:uart --> parsed 0142a1a8592815c6ab047e
2024-01-23T21:16:27.653Z zigbee-herdsman:adapter:ezsp:uart <-- DATA (0,1,0): 0142a1a8592815c6ab047e
2024-01-23T21:16:27.653Z zigbee-herdsman:adapter:ezsp:uart --> ACK  (1)
2024-01-23T21:16:27.654Z zigbee-herdsman:adapter:ezsp:uart --> [8160597e]
2024-01-23T21:16:27.655Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (1): 0142a1a8592815c6ab047e
2024-01-23T21:16:27.656Z zigbee-herdsman:adapter:ezsp:ezsp <== Frame: 0080000d020074
2024-01-23T21:16:27.657Z zigbee-herdsman:adapter:ezsp:ezsp <== 0x0: {"_cls_":"version","_id_":0,"_isRequest_":false,"protocolVersion":13,"stackType":2,"stackVersion":29696}
2024-01-23T21:16:27.659Z zigbee-herdsman:adapter:ezsp:uart -+- rewaiting (1) success
2024-01-23T21:16:27.659Z zigbee-herdsman:adapter:ezsp:ezsp Switching to eszp version 13
2024-01-23T21:16:27.660Z zigbee-herdsman:adapter:ezsp:ezsp ==> version: {"desiredProtocolVersion":13}
2024-01-23T21:16:27.660Z zigbee-herdsman:adapter:ezsp:ezsp ==> {"_cls_":"version","_id_":0,"_isRequest_":true,"desiredProtocolVersion":13}
2024-01-23T21:16:27.661Z zigbee-herdsman:adapter:ezsp:uart --> DATA (0,1,0): 01000100000d
2024-01-23T21:16:27.662Z zigbee-herdsman:adapter:ezsp:uart --> [014321a9542a7d38aea17e]
2024-01-23T21:16:27.662Z zigbee-herdsman:adapter:ezsp:uart -?- waiting (1)
2024-01-23T21:16:27.664Z zigbee-herdsman:adapter:ezsp:uart <-- [8160597e]
2024-01-23T21:16:27.664Z zigbee-herdsman:adapter:ezsp:uart --> parsed 8160597e
2024-01-23T21:16:27.664Z zigbee-herdsman:adapter:ezsp:uart <-- ACK (1): 8160597e
2024-01-23T21:16:27.665Z zigbee-herdsman:adapter:ezsp:uart -+- waiting (1) success
2024-01-23T21:16:28.650Z zigbee-herdsman:adapter:ezsp:uart <-- [a144]
2024-01-23T21:16:28.651Z zigbee-herdsman:adapter:ezsp:uart <-- [3b7e]
2024-01-23T21:16:28.651Z zigbee-herdsman:adapter:ezsp:uart --> parsed a1443b7e
2024-01-23T21:16:28.652Z zigbee-herdsman:adapter:ezsp:uart <-- NAK (1): a1443b7e
2024-01-23T21:16:28.652Z zigbee-herdsman:adapter:ezsp:uart NAK Unexpected packet sequence 1
2024-01-23T21:16:33.573Z zigbee-herdsman:adapter:ezsp:ezsp Time to watchdog ... 0
2024-01-23T21:16:33.573Z zigbee-herdsman:adapter:ezsp:ezsp ==> nop: null

SiLabs Multiprotocol

[2024-01-23T21:15:44.334445Z] Info : Secondary APP vUNDEFINED
[2024-01-23T21:15:44.334677Z] Info : Daemon startup was successful. Waiting for client connections
[2024-01-23T21:15:45.825920Z] Info : New client connection using library v4.4.0.0
[2024-01-23T21:15:45.828668Z] Info : Opened connection socket for ep#12
[2024-01-23T21:15:45.831555Z] Info : Endpoint socket #12: Client connected. 1 connection(s)
Listening on port 9999 for connection...

Accepting connection.

Accepted connection 8.

Restarting
[2024-01-23T21:16:23.562458Z] Info : Endpoint socket #12: Client disconnected. 0 connections
[2024-01-23T21:16:23.562661Z] Info : Client disconnected
[2024-01-23T21:16:24.565571Z] Info : New client connection using library v4.4.0.0
[2024-01-23T21:16:24.568432Z] Info : Opened connection socket for ep#12
[2024-01-23T21:16:24.571146Z] Info : Endpoint socket #12: Client connected. 1 connection(s)
Reusing socket from previous instance.

Socket connection has been closed, restarting...

Listening on port 9999 for connection...

Accepting connection.

Accepted connection 9.

Restarting
[2024-01-23T21:16:38.687566Z] Info : Endpoint socket #12: Client disconnected. 0 connections
[2024-01-23T21:16:38.687730Z] Info : Client disconnected
[2024-01-23T21:16:39.690400Z] Info : New client connection using library v4.4.0.0
[2024-01-23T21:16:39.693238Z] Info : Opened connection socket for ep#12
[2024-01-23T21:16:39.696036Z] Info : Endpoint socket #12: Client connected. 1 connection(s)
Reusing socket from previous instance.

Socket connection has been closed, restarting...

Listening on port 9999 for connection...

Accepting connection.

Accepted connection 10.

Restarting
[2024-01-23T21:25:40.057648Z] Info : Endpoint socket #12: Client disconnected. 0 connections
[2024-01-23T21:25:40.057851Z] Info : Client disconnected
[2024-01-23T21:25:41.061237Z] Info : New client connection using library v4.4.0.0
[2024-01-23T21:25:41.064223Z] Info : Opened connection socket for ep#12
[2024-01-23T21:25:41.067195Z] Info : Endpoint socket #12: Client connected. 1 connection(s)
Reusing socket from previo
wastez commented 9 months ago

Something bring the multiprotocol to crash and restart the port. I don't use it so I don't know all about it it. It has to have a debug mode too, this logs are to less to get the reasons why this happens.

RichardPar commented 9 months ago

Something bring the multiprotocol to crash and restart the port. I don't use it so I don't know all about it it. It has to have a debug mode too, this logs are to less to get the reasons why this happens.

Why when I restart Z2MQTT it all works fine? (Multiprotocol is not restarted) I have reproduced on 3 differenent installs too.
I can restatart Multiprotocol Addon and z2mqtt wont connect back first load... I dont know which side it is, but whichever it has made Z2MQTT sadly very unstable.

Nerivec commented 9 months ago

@RichardPar Can you try again once 0.33.2 is available to update and let me know if the behavior is better? If it's an underlaying issue with socket or silabs, of course, that won't fix the problem, but at least Z2M should handle the fail properly now. Well, hopefully anyway...

RichardPar commented 9 months ago

@RichardPar Can you try again once 0.33.2 is available to update and let me know if the behavior is better? If it's an underlaying issue with socket or silabs, of course, that won't fix the problem, but at least Z2M should handle the fail properly now. Well, hopefully anyway...

Installed and ran+connectesd first time ... I will put it through more paces and see how it purrs.

github-actions[bot] commented 3 months 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