Sudden failure to startup - timeout after SRSP - ZDO - startupFromApp

thargy commented 1 year ago

Symptom

Home Assistant Z2M addon no longer starts, reporting Error: SRSP - ZDO - startupFromApp after 40000ms. No changes were made that could explain the sudden fatal failure. Multiple hardware reboots have failed to have an impact.

Description

I've been running two instances of Z2m for about six months on two separate machines (an Intel NUC as a HAOS addon and a Rasberry Pi as a standalone Z2m instance) to allow me to run with two separate channels. Today at around 13:50, my Z2m HAOS addon instance on the Intel NUC died and refuses to restart. I had made no changes and was not interacting with Home Assistant or the hardware when it happened, and I have only been able to deduce the failure time from when various devices became 'unavailable' to HA. I did trigger a reboot around that time, though.

Sadly, my addon wasn't configured for Herdsman logging nor SSH access via 22222. By the time I got it all set up, the initial logs were gone. However, I eventually managed to grab the full log below.

I've checked, and my Sonoff Zigbee 3.0 USB Dongle Plus is still connected to the correct USB port. From the logs, there appears to be initial communication until it gets to SRSP - ZDO - startupFromApp, at which point it times out, and the docker container is unloaded (making grabbing logs difficult).

Have you any idea what may be causing this issue? I have a very large network (~150 devices), and rebuilding it would be a nightmare.

I have a coordinator backup from last night, so I could try restoring that to the dongle and upgrading to coordinator revision 20230507, which I've been running on the second dongle for several months. However, I wanted to let you look first and see if there were any logs or debug steps you'd like me to try. However, I can no longer control any of my house lights or automations, so I would appreciate any help you can provide quickly.

Data

System Properties for Intel NUC HA addon instance

Docker Log (up to timeout)

``` [22:37:26] INFO: Preparing to start... [22:37:26] INFO: Socat not enabled [22:37:26] INFO: Zigbee Herdsman debug logging enabled [22:37:26] INFO: Starting Zigbee2MQTT... 2023-09-19T21:37:28.106Z zigbee-herdsman:adapter Failed to validate path: 'Error: spawn udevadm ENOENT' 2023-09-19T21:37:28.107Z 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":"/dev/ttyUSB0"},"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-09-19T21:37:28.108Z zigbee-herdsman:adapter:zStack:znp:log Opening SerialPort with {"path":"/dev/ttyUSB0","baudRate":115200,"rtscts":false,"autoOpen":false} 2023-09-19T21:37:28.111Z zigbee-herdsman:adapter:zStack:znp:log Serialport opened 2023-09-19T21:37:28.112Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2023-09-19T21:37:28.112Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2023-09-19T21:37:28.365Z zigbee-herdsman:adapter:zStack:znp:log Writing CC2530/CC2531 skip bootloader payload 2023-09-19T21:37:28.365Z zigbee-herdsman:adapter:zStack:unpi:writer --> buffer [239] 2023-09-19T21:37:29.367Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2023-09-19T21:37:29.368Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2023-09-19T21:37:29.620Z zigbee-herdsman:adapter:zStack:znp:log Skip bootloader for CC2652/CC1352 2023-09-19T21:37:29.943Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [0] 2023-09-19T21:37:29.944Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [0] 2023-09-19T21:37:30.077Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2023-09-19T21:37:30.078Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2023-09-19T21:37:32.981Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,6,65,128,0,2,1,2,7,1,192] 2023-09-19T21:37:32.981Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [0,254,6,65,128,0,2,1,2,7,1,192] 2023-09-19T21:37:32.983Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 6 - 2 - 1 - 128 - [0,2,1,2,7,1] - 192 2023-09-19T21:37:32.984Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- SYS - resetInd - {"reason":0,"transportrev":2,"productid":1,"majorrel":2,"minorrel":7,"hwrev":1} 2023-09-19T21:37:32.985Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.080Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2023-09-19T21:37:36.080Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2023-09-19T21:37:36.084Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,1,89,6,61] 2023-09-19T21:37:36.084Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,1,89,6,61] 2023-09-19T21:37:36.084Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 1 - [89,6] - 61 2023-09-19T21:37:36.085Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - ping - {"capabilities":1625} 2023-09-19T21:37:36.085Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.086Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - version - {} 2023-09-19T21:37:36.086Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,2,35] 2023-09-19T21:37:36.089Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,10,97,2,2,1,2,7,1,42,141,52,1,0,252] 2023-09-19T21:37:36.089Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,10,97,2,2,1,2,7,1,42,141,52,1,0,252] 2023-09-19T21:37:36.089Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 10 - 3 - 1 - 2 - [2,1,2,7,1,42,141,52,1,0] - 252 2023-09-19T21:37:36.090Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - version - {"transportrev":2,"product":1,"majorrel":2,"minorrel":7,"maintrel":1,"revision":20221226} 2023-09-19T21:37:36.090Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.090Z zigbee-herdsman:adapter:zStack:adapter Adapter concurrent: 16 2023-09-19T21:37:36.090Z zigbee-herdsman:adapter:zStack:adapter Detected znp version 'zStack3x0' ({"transportrev":2,"product":1,"majorrel":2,"minorrel":7,"maintrel":1,"revision":20221226}) 2023-09-19T21:37:36.091Z zigbee-herdsman:adapter:zStack:startup beginning znp startup 2023-09-19T21:37:36.092Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - getExtAddr - {} 2023-09-19T21:37:36.092Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,4,37] 2023-09-19T21:37:36.095Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,8,97,4,139,7,126,37,0,75,18,0,227] 2023-09-19T21:37:36.095Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,8,97,4,139,7,126,37,0,75,18,0,227] 2023-09-19T21:37:36.095Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 8 - 3 - 1 - 4 - [139,7,126,37,0,75,18,0] - 227 2023-09-19T21:37:36.096Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - getExtAddr - {"extaddress":"0x00124b00257e078b"} 2023-09-19T21:37:36.096Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.097Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":130} 2023-09-19T21:37:36.097Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,130,0,178] 2023-09-19T21:37:36.101Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,24,0,104] 2023-09-19T21:37:36.101Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,24,0,104] 2023-09-19T21:37:36.101Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [24,0] - 104 2023-09-19T21:37:36.101Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":24} 2023-09-19T21:37:36.101Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.101Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":130,"offset":0} 2023-09-19T21:37:36.102Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,130,0,0,0,187] 2023-09-19T21:37:36.108Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,26,97,28,0,24,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,116,3,16,82,33,211,3,184] 2023-09-19T21:37:36.109Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,26,97,28,0,24,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,116,3,16,82,33,211,3,184] 2023-09-19T21:37:36.109Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 26 - 3 - 1 - 28 - [0,24,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,116,3,16,82,33,211,3] - 184 2023-09-19T21:37:36.110Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":24,"value":{"type":"Buffer","data":[0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,116,3,16,82,33,211,3]}} 2023-09-19T21:37:36.110Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.111Z zigbee-herdsman:adapter:zStack:startup:strategy determining znp startup strategy 2023-09-19T21:37:36.111Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":96} 2023-09-19T21:37:36.112Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,96,0,80] 2023-09-19T21:37:36.116Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,1,0,113] 2023-09-19T21:37:36.116Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,1,0,113] 2023-09-19T21:37:36.116Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [1,0] - 113 2023-09-19T21:37:36.116Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":1} 2023-09-19T21:37:36.116Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.116Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":96,"offset":0} 2023-09-19T21:37:36.117Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,96,0,0,0,89] 2023-09-19T21:37:36.122Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,97,28,0,1,85,42] 2023-09-19T21:37:36.122Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,97,28,0,1,85,42] 2023-09-19T21:37:36.122Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 3 - 1 - 28 - [0,1,85] - 42 2023-09-19T21:37:36.122Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":1,"value":{"type":"Buffer","data":[85]}} 2023-09-19T21:37:36.122Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.124Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":33} 2023-09-19T21:37:36.124Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,33,0,17] 2023-09-19T21:37:36.132Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,116,0,4] 2023-09-19T21:37:36.132Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,116,0,4] 2023-09-19T21:37:36.132Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [116,0] - 4 2023-09-19T21:37:36.132Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":116} 2023-09-19T21:37:36.132Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.133Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":33,"offset":0} 2023-09-19T21:37:36.133Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,33,0,0,0,24] 2023-09-19T21:37:36.156Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,118,97,28,0,116,253,5,2,101,15,101,0,30,0,0,0,1,5,1,143,0,7,0,2,13,2,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,98,26,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,139,7,126,37,0,75,18,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,60,10,1,0,0,0,35,185,0,0,74] 2023-09-19T21:37:36.156Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,118,97,28,0,116,253,5,2,101,15,101,0,30,0,0,0,1,5,1,143,0,7,0,2,13,2,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,98,26,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,139,7,126,37,0,75,18,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,60,10,1,0,0,0,35,185,0,0,74] 2023-09-19T21:37:36.156Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 118 - 3 - 1 - 28 - [0,116,253,5,2,101,15,101,0,30,0,0,0,1,5,1,143,0,7,0,2,13,2,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,98,26,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,139,7,126,37,0,75,18,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,60,10,1,0,0,0,35,185,0,0] - 74 2023-09-19T21:37:36.156Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":116,"value":{"type":"Buffer","data":[253,5,2,101,15,101,0,30,0,0,0,1,5,1,143,0,7,0,2,13,2,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,98,26,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,139,7,126,37,0,75,18,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,60,10,1,0,0,0,35,185,0,0]}} 2023-09-19T21:37:36.157Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.158Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":98} 2023-09-19T21:37:36.158Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,98,0,82] 2023-09-19T21:37:36.167Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,16,0,96] 2023-09-19T21:37:36.168Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,16,0,96] 2023-09-19T21:37:36.168Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [16,0] - 96 2023-09-19T21:37:36.168Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":16} 2023-09-19T21:37:36.169Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.169Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":98,"offset":0} 2023-09-19T21:37:36.169Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,98,0,0,0,91] 2023-09-19T21:37:36.187Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,18,97,28,0,16,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T21:37:36.187Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,18,97,28,0,16,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T21:37:36.187Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 18 - 3 - 1 - 28 - [0,16,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13] - 124 2023-09-19T21:37:36.187Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":16,"value":{"type":"Buffer","data":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]}} 2023-09-19T21:37:36.187Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.188Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":58} 2023-09-19T21:37:36.188Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,58,0,10] 2023-09-19T21:37:36.197Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,17,0,97] 2023-09-19T21:37:36.198Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,17,0,97] 2023-09-19T21:37:36.198Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [17,0] - 97 2023-09-19T21:37:36.198Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":17} 2023-09-19T21:37:36.198Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.198Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":58,"offset":0} 2023-09-19T21:37:36.198Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,58,0,0,0,3] 2023-09-19T21:37:36.216Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,19,97,28,0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T21:37:36.216Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,19,97,28,0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T21:37:36.216Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 19 - 3 - 1 - 28 - [0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13] - 124 2023-09-19T21:37:36.216Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":17,"value":{"type":"Buffer","data":[0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]}} 2023-09-19T21:37:36.216Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.216Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":59} 2023-09-19T21:37:36.216Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,59,0,11] 2023-09-19T21:37:36.226Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,17,0,97] 2023-09-19T21:37:36.226Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,17,0,97] 2023-09-19T21:37:36.226Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [17,0] - 97 2023-09-19T21:37:36.226Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":17} 2023-09-19T21:37:36.226Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.226Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":59,"offset":0} 2023-09-19T21:37:36.226Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,59,0,0,0,2] 2023-09-19T21:37:36.244Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,19,97,28,0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T21:37:36.245Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,19,97,28,0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T21:37:36.245Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 19 - 3 - 1 - 28 - [0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13] - 124 2023-09-19T21:37:36.245Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":17,"value":{"type":"Buffer","data":[0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]}} 2023-09-19T21:37:36.245Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.253Z zigbee-herdsman:adapter:zStack:startup:strategy (stage-1) adapter is configured 2023-09-19T21:37:36.253Z zigbee-herdsman:adapter:zStack:startup:strategy (stage-2) adapter state matches configuration 2023-09-19T21:37:36.253Z zigbee-herdsman:adapter:zStack:startup determined startup strategy: startup 2023-09-19T21:37:36.254Z zigbee-herdsman:adapter:zStack:znp:SREQ --> UTIL - getDeviceInfo - {} 2023-09-19T21:37:36.254Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,39,0,39] 2023-09-19T21:37:36.264Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,14,103,0,0,139,7,126,37,0,75,18,0,254,255,7,0,0,225] 2023-09-19T21:37:36.264Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,14,103,0,0,139,7,126,37,0,75,18,0,254,255,7,0,0,225] 2023-09-19T21:37:36.264Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 14 - 3 - 7 - 0 - [0,139,7,126,37,0,75,18,0,254,255,7,0,0] - 225 2023-09-19T21:37:36.265Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- UTIL - getDeviceInfo - {"status":0,"ieeeaddr":"0x00124b00257e078b","shortaddr":65534,"devicetype":7,"devicestate":0,"numassocdevices":0,"assocdeviceslist":[]} 2023-09-19T21:37:36.265Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T21:37:36.265Z zigbee-herdsman:adapter:zStack:startup starting adapter as coordinator 2023-09-19T21:37:36.265Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - startupFromApp - {"startdelay":100} 2023-09-19T21:37:36.265Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,37,64,100,0,3] ```

Z2M Log (on timeout)

``` error 2023-09-19 21:38:16: Error while starting zigbee-herdsman error 2023-09-19 21:38:16: Failed to start zigbee error 2023-09-19 21:38:16: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions error 2023-09-19 21:38:16: Exiting... error 2023-09-19 21:38:16: Error: SRSP - ZDO - startupFromApp after 40000ms at Timeout._onTimeout (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:64:35) at listOnTimeout (node:internal/timers:559:17) at processTimers (node:internal/timers:502:7) ```

thargy commented 1 year ago

OK, so being an unforgivably impatient sort, I backed up the coordinator and updated to 20230507. This went flawlessly, but I had exactly the same issue on starting the addon.

You can see from the log that the firmware has updated:

Docker Log (Same failure but updated coordinator firmware)

``` [23:54:07] INFO: Preparing to start... [23:54:07] INFO: Socat not enabled [23:54:07] INFO: Zigbee Herdsman debug logging enabled [23:54:07] INFO: Starting Zigbee2MQTT... 2023-09-19T22:54:09.106Z zigbee-herdsman:adapter Failed to validate path: 'Error: spawn udevadm ENOENT' 2023-09-19T22:54:09.107Z 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":"/dev/ttyUSB0"},"datab asePath":"/config/zigbee2mqtt/database.db","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","backupPath":"/config/zigbee2mqtt/coordinator_backup.json","adapter":{"disableLED":false,"concurrent":null,"delay":null}}' 2023-09-19T22:54:09.107Z zigbee-herdsman:adapter:zStack:znp:log Opening SerialPort with {"path":"/dev/ttyUSB0","baudRate":115200,"rtscts":false,"autoOpen":false} 2023-09-19T22:54:09.111Z zigbee-herdsman:adapter:zStack:znp:log Serialport opened 2023-09-19T22:54:09.112Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2023-09-19T22:54:09.112Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2023-09-19T22:54:09.364Z zigbee-herdsman:adapter:zStack:znp:log Writing CC2530/CC2531 skip bootloader payload 2023-09-19T22:54:09.365Z zigbee-herdsman:adapter:zStack:unpi:writer --> buffer [239] 2023-09-19T22:54:10.368Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2023-09-19T22:54:10.368Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2023-09-19T22:54:10.619Z zigbee-herdsman:adapter:zStack:znp:log Skip bootloader for CC2652/CC1352 2023-09-19T22:54:11.077Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2023-09-19T22:54:11.078Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2023-09-19T22:54:13.321Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,6,65,128,0,2,1,2,7,1,192] 2023-09-19T22:54:13.322Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,6,65,128,0,2,1,2,7,1,192] 2023-09-19T22:54:13.323Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 6 - 2 - 1 - 128 - [0,2,1,2,7,1] - 192 2023-09-19T22:54:13.324Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- SYS - resetInd - {"reason":0,"transportrev":2,"productid":1,"majorrel":2,"minorrel":7,"hwrev":1} 2023-09-19T22:54:13.324Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.080Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2023-09-19T22:54:17.081Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2023-09-19T22:54:17.084Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,1,89,6,61] 2023-09-19T22:54:17.084Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,1,89,6,61] 2023-09-19T22:54:17.084Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 1 - [89,6] - 61 2023-09-19T22:54:17.085Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - ping - {"capabilities":1625} 2023-09-19T22:54:17.085Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.085Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - version - {} 2023-09-19T22:54:17.086Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,2,35] 2023-09-19T22:54:17.089Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,10,97,2,2,1,2,7,1,107,177,52,1,0,129] 2023-09-19T22:54:17.089Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,10,97,2,2,1,2,7,1,107,177,52,1,0,129] 2023-09-19T22:54:17.089Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 10 - 3 - 1 - 2 - [2,1,2,7,1,107,177,52,1,0] - 129 2023-09-19T22:54:17.090Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - version - {"transportrev":2,"product":1,"majorrel":2,"minorrel":7,"maintrel":1,"revision":20230507} 2023-09-19T22:54:17.090Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.090Z zigbee-herdsman:adapter:zStack:adapter Adapter concurrent: 16 2023-09-19T22:54:17.090Z zigbee-herdsman:adapter:zStack:adapter Detected znp version 'zStack3x0' ({"transportrev":2,"product":1,"majorrel":2,"minorrel":7,"maintrel":1,"revision":20230507}) 2023-09-19T22:54:17.091Z zigbee-herdsman:adapter:zStack:startup beginning znp startup 2023-09-19T22:54:17.091Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - getExtAddr - {} 2023-09-19T22:54:17.092Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,4,37] 2023-09-19T22:54:17.095Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,8,97,4,139,7,126,37,0,75,18,0,227] 2023-09-19T22:54:17.095Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,8,97,4,139,7,126,37,0,75,18,0,227] 2023-09-19T22:54:17.095Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 8 - 3 - 1 - 4 - [139,7,126,37,0,75,18,0] - 227 2023-09-19T22:54:17.095Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - getExtAddr - {"extaddress":"0x00124b00257e078b"} 2023-09-19T22:54:17.096Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.096Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":130} 2023-09-19T22:54:17.097Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,130,0,178] 2023-09-19T22:54:17.102Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,24,0,104] 2023-09-19T22:54:17.102Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,24,0,104] 2023-09-19T22:54:17.102Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [24,0] - 104 2023-09-19T22:54:17.102Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":24} 2023-09-19T22:54:17.102Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.103Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":130,"offset":0} 2023-09-19T22:54:17.103Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,130,0,0,0,187] 2023-09-19T22:54:17.113Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,26,97,28,0,24,0,191,40,235,187,243,14,236,60,196,177,156,167,23,22,46,236,191,40,235,0,0,0,0,100] 2023-09-19T22:54:17.113Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,26,97,28,0,24,0,191,40,235,187,243,14,236,60,196,177,156,167,23,22,46,236,191,40,235,0,0,0,0,100] 2023-09-19T22:54:17.113Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 26 - 3 - 1 - 28 - [0,24,0,191,40,235,187,243,14,236,60,196,177,156,167,23,22,46,236,191,40,235,0,0,0,0] - 100 2023-09-19T22:54:17.114Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":24,"value":{"type":"Buffer","data":[0,191,40,235,187,243,14,236,60,196,177,156,167,23,22,46,236,191,40,235,0,0,0,0]}} 2023-09-19T22:54:17.114Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.115Z zigbee-herdsman:adapter:zStack:startup:strategy determining znp startup strategy 2023-09-19T22:54:17.115Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":96} 2023-09-19T22:54:17.116Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,96,0,80] 2023-09-19T22:54:17.123Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,1,0,113] 2023-09-19T22:54:17.123Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,1,0,113] 2023-09-19T22:54:17.123Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [1,0] - 113 2023-09-19T22:54:17.124Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":1} 2023-09-19T22:54:17.124Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.124Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":96,"offset":0} 2023-09-19T22:54:17.124Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,96,0,0,0,89] 2023-09-19T22:54:17.137Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,97,28,0,1,85,42] 2023-09-19T22:54:17.137Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,97,28,0,1,85,42] 2023-09-19T22:54:17.137Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 3 - 1 - 28 - [0,1,85] - 42 2023-09-19T22:54:17.137Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":1,"value":{"type":"Buffer","data":[85]}} 2023-09-19T22:54:17.138Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.140Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":33} 2023-09-19T22:54:17.140Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,33,0,17] 2023-09-19T22:54:17.148Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,116,0,4] 2023-09-19T22:54:17.149Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,116,0,4] 2023-09-19T22:54:17.149Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [116,0] - 4 2023-09-19T22:54:17.149Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":116} 2023-09-19T22:54:17.149Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.149Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":33,"offset":0} 2023-09-19T22:54:17.150Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,33,0,0,0,24] 2023-09-19T22:54:17.186Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,118,97,28,0,116,115,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,98,26,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,139,7,126,37,0,75,18,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0 ,0,0,0,0,0,0,0,0,0,0,15,5,0,1,120,10,1,0,0,0,0,0,0,0,233] 2023-09-19T22:54:17.186Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,118,97,28,0,116,115,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,98,26,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,139,7,126,37,0,75,18,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0 ,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,120,10,1,0,0,0,0,0,0,0,233] 2023-09-19T22:54:17.187Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 118 - 3 - 1 - 28 - [0,116,115,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,98,26,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,139,7,126,37,0,75,18,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0 ,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,120,10,1,0,0,0,0,0,0,0] - 233 2023-09-19T22:54:17.187Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":116,"value":{"type":"Buffer","data":[115,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,98,26,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,139,7,126,37,0,75,18,0, 1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,120,10,1,0,0,0,0,0,0,0]}} 2023-09-19T22:54:17.187Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.190Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":98} 2023-09-19T22:54:17.190Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,98,0,82] 2023-09-19T22:54:17.198Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,16,0,96] 2023-09-19T22:54:17.198Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,16,0,96] 2023-09-19T22:54:17.199Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [16,0] - 96 2023-09-19T22:54:17.199Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":16} 2023-09-19T22:54:17.199Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.199Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":98,"offset":0} 2023-09-19T22:54:17.199Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,98,0,0,0,91] 2023-09-19T22:54:17.215Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,18,97,28,0,16,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T22:54:17.215Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,18,97,28,0,16,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T22:54:17.215Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 18 - 3 - 1 - 28 - [0,16,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13] - 124 2023-09-19T22:54:17.215Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":16,"value":{"type":"Buffer","data":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]}} 2023-09-19T22:54:17.216Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.216Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":58} 2023-09-19T22:54:17.217Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,58,0,10] 2023-09-19T22:54:17.225Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,17,0,97] 2023-09-19T22:54:17.225Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,17,0,97] 2023-09-19T22:54:17.225Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [17,0] - 97 2023-09-19T22:54:17.225Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":17} 2023-09-19T22:54:17.225Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.225Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":58,"offset":0} 2023-09-19T22:54:17.226Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,58,0,0,0,3] 2023-09-19T22:54:17.242Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,19,97,28,0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T22:54:17.242Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,19,97,28,0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T22:54:17.242Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 19 - 3 - 1 - 28 - [0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13] - 124 2023-09-19T22:54:17.242Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":17,"value":{"type":"Buffer","data":[0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]}} 2023-09-19T22:54:17.242Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.243Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":59} 2023-09-19T22:54:17.243Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,59,0,11] 2023-09-19T22:54:17.251Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,17,0,97] 2023-09-19T22:54:17.251Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,17,0,97] 2023-09-19T22:54:17.251Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [17,0] - 97 2023-09-19T22:54:17.252Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":17} 2023-09-19T22:54:17.252Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.252Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":59,"offset":0} 2023-09-19T22:54:17.252Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,59,0,0,0,2] 2023-09-19T22:54:17.268Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,19,97,28,0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T22:54:17.268Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,19,97,28,0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T22:54:17.268Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 19 - 3 - 1 - 28 - [0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13] - 124 2023-09-19T22:54:17.269Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":17,"value":{"type":"Buffer","data":[0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]}} 2023-09-19T22:54:17.269Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.277Z zigbee-herdsman:adapter:zStack:startup:strategy (stage-1) adapter is configured 2023-09-19T22:54:17.277Z zigbee-herdsman:adapter:zStack:startup:strategy (stage-2) adapter state matches configuration 2023-09-19T22:54:17.277Z zigbee-herdsman:adapter:zStack:startup determined startup strategy: startup 2023-09-19T22:54:17.278Z zigbee-herdsman:adapter:zStack:znp:SREQ --> UTIL - getDeviceInfo - {} 2023-09-19T22:54:17.278Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,39,0,39] 2023-09-19T22:54:17.287Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,14,103,0,0,139,7,126,37,0,75,18,0,254,255,7,0,0,225] 2023-09-19T22:54:17.287Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,14,103,0,0,139,7,126,37,0,75,18,0,254,255,7,0,0,225] 2023-09-19T22:54:17.287Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 14 - 3 - 7 - 0 - [0,139,7,126,37,0,75,18,0,254,255,7,0,0] - 225 2023-09-19T22:54:17.288Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- UTIL - getDeviceInfo - {"status":0,"ieeeaddr":"0x00124b00257e078b","shortaddr":65534,"devicetype":7,"devicestate":0,"numassocdevices":0,"assocdeviceslist":[]} 2023-09-19T22:54:17.288Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:54:17.288Z zigbee-herdsman:adapter:zStack:startup starting adapter as coordinator 2023-09-19T22:54:17.289Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - startupFromApp - {"startdelay":100} 2023-09-19T22:54:17.289Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,37,64,100,0,3] Zigbee2MQTT:error 2023-09-19 23:54:57: Error while starting zigbee-herdsman Zigbee2MQTT:error 2023-09-19 23:54:57: Failed to start zigbee Zigbee2MQTT:error 2023-09-19 23:54:57: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions Zigbee2MQTT:error 2023-09-19 23:54:57: Exiting... Zigbee2MQTT:error 2023-09-19 23:54:57: Error: SRSP - ZDO - startupFromApp after 40000ms at Timeout._onTimeout (/app/node_modules/zigbee-herdsman/src/utils/waitress.ts:64:35) at listOnTimeout (node:internal/timers:559:17) at processTimers (node:internal/timers:502:7) ```

However, whilst I was coming here to post, the watchdog started it again, and this time it booted up as usual!!!

I have restarted several times and turned off herdsman logging to see if it survives restarts, and it does. However, out of 157 devices, only 58 have reported back in so far, and it seems to have stalled at that number, so I need to give it some time to see if I can get the full network to rebuild.

Docker Log (truncated after startupFromApp succeeds)

``` [23:54:57] INFO: [32mPreparing to start...[0m [23:54:57] INFO: [32mSocat not enabled[0m [23:54:58] INFO: [32mZigbee Herdsman debug logging enabled[0m [23:54:58] INFO: [32mStarting Zigbee2MQTT...[0m 2023-09-19T22:54:59.577Z zigbee-herdsman:adapter Failed to validate path: 'Error: spawn udevadm ENOENT' 2023-09-19T22:54:59.578Z 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":"/dev/ttyUSB0"},"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-09-19T22:54:59.579Z zigbee-herdsman:adapter:zStack:znp:log Opening SerialPort with {"path":"/dev/ttyUSB0","baudRate":115200,"rtscts":false,"autoOpen":false} 2023-09-19T22:54:59.583Z zigbee-herdsman:adapter:zStack:znp:log Serialport opened 2023-09-19T22:54:59.584Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2023-09-19T22:54:59.584Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2023-09-19T22:54:59.837Z zigbee-herdsman:adapter:zStack:znp:log Writing CC2530/CC2531 skip bootloader payload 2023-09-19T22:54:59.838Z zigbee-herdsman:adapter:zStack:unpi:writer --> buffer [239] 2023-09-19T22:55:00.840Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2023-09-19T22:55:00.841Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2023-09-19T22:55:01.092Z zigbee-herdsman:adapter:zStack:znp:log Skip bootloader for CC2652/CC1352 2023-09-19T22:55:01.549Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2023-09-19T22:55:01.550Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2023-09-19T22:55:03.550Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,6,65,128,0,2,1,2,7,1,192] 2023-09-19T22:55:03.551Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,6,65,128,0,2,1,2,7,1,192] 2023-09-19T22:55:03.551Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 6 - 2 - 1 - 128 - [0,2,1,2,7,1] - 192 2023-09-19T22:55:03.553Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- SYS - resetInd - {"reason":0,"transportrev":2,"productid":1,"majorrel":2,"minorrel":7,"hwrev":1} 2023-09-19T22:55:03.553Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.552Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2023-09-19T22:55:07.553Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2023-09-19T22:55:07.556Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,1,89,6,61] 2023-09-19T22:55:07.556Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,1,89,6,61] 2023-09-19T22:55:07.556Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 1 - [89,6] - 61 2023-09-19T22:55:07.556Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - ping - {"capabilities":1625} 2023-09-19T22:55:07.557Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.557Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - version - {} 2023-09-19T22:55:07.557Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,2,35] 2023-09-19T22:55:07.560Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,10,97,2,2,1,2,7,1,107,177,52,1,0,129] 2023-09-19T22:55:07.560Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,10,97,2,2,1,2,7,1,107,177,52,1,0,129] 2023-09-19T22:55:07.560Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 10 - 3 - 1 - 2 - [2,1,2,7,1,107,177,52,1,0] - 129 2023-09-19T22:55:07.561Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - version - {"transportrev":2,"product":1,"majorrel":2,"minorrel":7,"maintrel":1,"revision":20230507} 2023-09-19T22:55:07.561Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.561Z zigbee-herdsman:adapter:zStack:adapter Adapter concurrent: 16 2023-09-19T22:55:07.561Z zigbee-herdsman:adapter:zStack:adapter Detected znp version 'zStack3x0' ({"transportrev":2,"product":1,"majorrel":2,"minorrel":7,"maintrel":1,"revision":20230507}) 2023-09-19T22:55:07.562Z zigbee-herdsman:adapter:zStack:startup beginning znp startup 2023-09-19T22:55:07.562Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - getExtAddr - {} 2023-09-19T22:55:07.563Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,4,37] 2023-09-19T22:55:07.566Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,8,97,4,139,7,126,37,0,75,18,0,227] 2023-09-19T22:55:07.566Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,8,97,4,139,7,126,37,0,75,18,0,227] 2023-09-19T22:55:07.566Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 8 - 3 - 1 - 4 - [139,7,126,37,0,75,18,0] - 227 2023-09-19T22:55:07.567Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - getExtAddr - {"extaddress":"0x00124b00257e078b"} 2023-09-19T22:55:07.567Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.567Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":130} 2023-09-19T22:55:07.568Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,130,0,178] 2023-09-19T22:55:07.576Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,24,0,104] 2023-09-19T22:55:07.576Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,24,0,104] 2023-09-19T22:55:07.576Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [24,0] - 104 2023-09-19T22:55:07.576Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":24} 2023-09-19T22:55:07.576Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.577Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":130,"offset":0} 2023-09-19T22:55:07.577Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,130,0,0,0,187] 2023-09-19T22:55:07.593Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,26,97,28,0,24,0,191,40,235,187,243,14,236,60,196,177,156,167,23,22,46,236,191,40,235,0,0,0,0,100] 2023-09-19T22:55:07.593Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,26,97,28,0,24,0,191,40,235,187,243,14,236,60,196,177,156,167,23,22,46,236,191,40,235,0,0,0,0,100] 2023-09-19T22:55:07.593Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 26 - 3 - 1 - 28 - [0,24,0,191,40,235,187,243,14,236,60,196,177,156,167,23,22,46,236,191,40,235,0,0,0,0] - 100 2023-09-19T22:55:07.594Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":24,"value":{"type":"Buffer","data":[0,191,40,235,187,243,14,236,60,196,177,156,167,23,22,46,236,191,40,235,0,0,0,0]}} 2023-09-19T22:55:07.594Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.596Z zigbee-herdsman:adapter:zStack:startup:strategy determining znp startup strategy 2023-09-19T22:55:07.596Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":96} 2023-09-19T22:55:07.596Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,96,0,80] 2023-09-19T22:55:07.600Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,1,0,113] 2023-09-19T22:55:07.600Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,1,0,113] 2023-09-19T22:55:07.600Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [1,0] - 113 2023-09-19T22:55:07.600Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":1} 2023-09-19T22:55:07.600Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.601Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":96,"offset":0} 2023-09-19T22:55:07.601Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,96,0,0,0,89] 2023-09-19T22:55:07.605Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,97,28,0,1,85,42] 2023-09-19T22:55:07.605Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,97,28,0,1,85,42] 2023-09-19T22:55:07.605Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 3 - 1 - 28 - [0,1,85] - 42 2023-09-19T22:55:07.606Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":1,"value":{"type":"Buffer","data":[85]}} 2023-09-19T22:55:07.606Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.608Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":33} 2023-09-19T22:55:07.608Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,33,0,17] 2023-09-19T22:55:07.613Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,116,0,4] 2023-09-19T22:55:07.613Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,116,0,4] 2023-09-19T22:55:07.613Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [116,0] - 4 2023-09-19T22:55:07.613Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":116} 2023-09-19T22:55:07.613Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.613Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":33,"offset":0} 2023-09-19T22:55:07.614Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,33,0,0,0,24] 2023-09-19T22:55:07.636Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,118,97,28,0,116,115,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,98,26,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,139,7,126,37,0,75,18,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,120,10,1,0,0,0,0,0,0,0,233] 2023-09-19T22:55:07.636Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,118,97,28,0,116,115,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,98,26,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,139,7,126,37,0,75,18,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,120,10,1,0,0,0,0,0,0,0,233] 2023-09-19T22:55:07.636Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 118 - 3 - 1 - 28 - [0,116,115,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,98,26,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,139,7,126,37,0,75,18,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,120,10,1,0,0,0,0,0,0,0] - 233 2023-09-19T22:55:07.637Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":116,"value":{"type":"Buffer","data":[115,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,98,26,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,139,7,126,37,0,75,18,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,120,10,1,0,0,0,0,0,0,0]}} 2023-09-19T22:55:07.637Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.639Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":98} 2023-09-19T22:55:07.639Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,98,0,82] 2023-09-19T22:55:07.643Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,16,0,96] 2023-09-19T22:55:07.643Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,16,0,96] 2023-09-19T22:55:07.643Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [16,0] - 96 2023-09-19T22:55:07.643Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":16} 2023-09-19T22:55:07.643Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.643Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":98,"offset":0} 2023-09-19T22:55:07.643Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,98,0,0,0,91] 2023-09-19T22:55:07.651Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,18,97,28,0,16,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T22:55:07.651Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,18,97,28,0,16,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T22:55:07.651Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 18 - 3 - 1 - 28 - [0,16,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13] - 124 2023-09-19T22:55:07.651Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":16,"value":{"type":"Buffer","data":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]}} 2023-09-19T22:55:07.651Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.652Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":58} 2023-09-19T22:55:07.652Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,58,0,10] 2023-09-19T22:55:07.656Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,17,0,97] 2023-09-19T22:55:07.656Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,17,0,97] 2023-09-19T22:55:07.656Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [17,0] - 97 2023-09-19T22:55:07.656Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":17} 2023-09-19T22:55:07.656Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.656Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":58,"offset":0} 2023-09-19T22:55:07.656Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,58,0,0,0,3] 2023-09-19T22:55:07.664Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,19,97,28,0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T22:55:07.664Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,19,97,28,0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T22:55:07.664Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 19 - 3 - 1 - 28 - [0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13] - 124 2023-09-19T22:55:07.664Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":17,"value":{"type":"Buffer","data":[0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]}} 2023-09-19T22:55:07.665Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.665Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":59} 2023-09-19T22:55:07.665Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,59,0,11] 2023-09-19T22:55:07.669Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,17,0,97] 2023-09-19T22:55:07.669Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,17,0,97] 2023-09-19T22:55:07.669Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [17,0] - 97 2023-09-19T22:55:07.670Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":17} 2023-09-19T22:55:07.670Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.670Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":59,"offset":0} 2023-09-19T22:55:07.670Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,59,0,0,0,2] 2023-09-19T22:55:07.678Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,19,97,28,0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T22:55:07.678Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,19,97,28,0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-19T22:55:07.678Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 19 - 3 - 1 - 28 - [0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13] - 124 2023-09-19T22:55:07.678Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":17,"value":{"type":"Buffer","data":[0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]}} 2023-09-19T22:55:07.678Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.685Z zigbee-herdsman:adapter:zStack:startup:strategy (stage-1) adapter is configured 2023-09-19T22:55:07.685Z zigbee-herdsman:adapter:zStack:startup:strategy (stage-2) adapter state matches configuration 2023-09-19T22:55:07.685Z zigbee-herdsman:adapter:zStack:startup determined startup strategy: startup 2023-09-19T22:55:07.685Z zigbee-herdsman:adapter:zStack:znp:SREQ --> UTIL - getDeviceInfo - {} 2023-09-19T22:55:07.685Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,39,0,39] 2023-09-19T22:55:07.690Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,14,103,0,0,139,7,126,37,0,75,18,0,254,255,7,0,0,225] 2023-09-19T22:55:07.690Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,14,103,0,0,139,7,126,37,0,75,18,0,254,255,7,0,0,225] 2023-09-19T22:55:07.691Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 14 - 3 - 7 - 0 - [0,139,7,126,37,0,75,18,0,254,255,7,0,0] - 225 2023-09-19T22:55:07.691Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- UTIL - getDeviceInfo - {"status":0,"ieeeaddr":"0x00124b00257e078b","shortaddr":65534,"devicetype":7,"devicestate":0,"numassocdevices":0,"assocdeviceslist":[]} 2023-09-19T22:55:07.691Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:07.691Z zigbee-herdsman:adapter:zStack:startup starting adapter as coordinator 2023-09-19T22:55:07.691Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - startupFromApp - {"startdelay":100} 2023-09-19T22:55:07.692Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,37,64,100,0,3] 2023-09-19T22:55:11.562Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,64,0,36,254,1,69,192,9,141,254,3,79,128,13,0,4,197] 2023-09-19T22:55:11.563Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,64,0,36,254,1,69,192,9,141,254,3,79,128,13,0,4,197] 2023-09-19T22:55:11.563Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 64 - [0] - 36 2023-09-19T22:55:11.563Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - startupFromApp - {"status":0} 2023-09-19T22:55:11.564Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,69,192,9,141,254,3,79,128,13,0,4,197] 2023-09-19T22:55:11.564Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 2 - 5 - 192 - [9] - 141 2023-09-19T22:55:11.564Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - stateChangeInd - {"state":9} 2023-09-19T22:55:11.564Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,79,128,13,0,4,197] 2023-09-19T22:55:11.564Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 2 - 15 - 128 - [13,0,4] - 197 2023-09-19T22:55:11.565Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- APP_CNF - bdbComissioningNotifcation - {"status":13} 2023-09-19T22:55:11.565Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:11.565Z zigbee-herdsman:adapter:zStack:startup adapter successfully started in coordinator mode 2023-09-19T22:55:11.565Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - activeEpReq - {"dstaddr":0,"nwkaddrofinterest":0} 2023-09-19T22:55:11.566Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,37,5,0,0,0,0,36] 2023-09-19T22:55:11.597Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,101,5,0,97,254,6,69,133,0,0,0,0,0,0,198] 2023-09-19T22:55:11.597Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,101,5,0,97,254,6,69,133,0,0,0,0,0,0,198] 2023-09-19T22:55:11.597Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 5 - 5 - [0] - 97 2023-09-19T22:55:11.597Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- ZDO - activeEpReq - {"status":0} 2023-09-19T22:55:11.598Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,6,69,133,0,0,0,0,0,0,198] 2023-09-19T22:55:11.598Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 6 - 2 - 5 - 133 - [0,0,0,0,0,0] - 198 2023-09-19T22:55:11.598Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- ZDO - activeEpRsp - {"srcaddr":0,"status":0,"nwkaddr":0,"activeepcount":0,"activeeplist":[]} 2023-09-19T22:55:11.598Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-19T22:55:11.598Z zigbee-herdsman:adapter:zStack:startup registering endpoint '1' 2023-09-19T22:55:11.598Z zigbee-herdsman:adapter:zStack:znp:SREQ --> AF - register - {"appdeviceid":5,"appdevver":0,"appnuminclusters":0,"appinclusterlist":[],"appnumoutclusters":0,"appoutclusterlist":[],"latencyreq":0,"endpoint":1,"appprofid":260} 2023-09-19T22:55:11.599Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,9,36,0,1,4,1,5,0,0,0,0,0,44] 2023-09-19T22:55:11.602Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,1,100,0,0,101] 2023-09-19T22:55:11.602Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,1,100,0,0,101] 2023-09-19T22:55:11.602Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 1 - 3 - 4 - 0 - [0] - 101 2023-09-19T22:55:11.602Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- AF - register - {"status":0} 2023-09-19T22:55:11.602Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] ... ```

thargy commented 1 year ago

Update: Z2M ran for approx. 12 hours, it was mostly issuing regular warnings such as:

warn  2023-09-20 14:23:44: Failed to ping 'Hallway Rear Spot 1' (attempt 1/1, Read 0x001788010d974eb5/11 genBasic(["zclVersion"], {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Data request failed with error: 'No network route' (205)))

As a number of devices remained 'offline' to Z2m (but were responding to group messages). About 2/3rds of devices were communicating OK, the rest were responding to the groups (even if showing as 'No Network route' to Z2m.

After 12 hours the errors started appearing in the logs, e.g.

error 2023-09-20 14:35:34: Publish 'set' 'state' to 'Bedroom 2 Spots' failed: 'Error: Command 7 genLevelCtrl.moveToLevelWithOnOff({"level":0,"transtime":50}) failed (SRSP - AF - dataRequestExt after 6000ms)'

About 3-4 hours later devices stopped responding entirely and went offline, and pretty much every error and warning was for (SRSP - AF - dataRequestExt after 6000ms)

I noticed about 3 hours later and attempted to restart Z2m, at which point the above failure started and z2m is back to the refusing to start state, due to the timeout Error: SRSP - ZDO - startupFromApp after 40000ms. The log is essentially identical to the first log seen in the above comment:

Docker log showing failure to start

``` [21:21:53] INFO: [32mPreparing to start...[0m [21:21:53] INFO: [32mSocat not enabled[0m [21:21:53] INFO: [32mZigbee Herdsman debug logging enabled[0m [21:21:54] INFO: [32mStarting Zigbee2MQTT...[0m 2023-09-20T20:21:55.515Z zigbee-herdsman:adapter Failed to validate path: 'Error: spawn udevadm ENOENT' 2023-09-20T20:21:55.516Z 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":"/dev/ttyUSB0"},"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-09-20T20:21:55.516Z zigbee-herdsman:adapter:zStack:znp:log Opening SerialPort with {"path":"/dev/ttyUSB0","baudRate":115200,"rtscts":false,"autoOpen":false} 2023-09-20T20:21:55.520Z zigbee-herdsman:adapter:zStack:znp:log Serialport opened 2023-09-20T20:21:55.521Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2023-09-20T20:21:55.521Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2023-09-20T20:21:55.774Z zigbee-herdsman:adapter:zStack:znp:log Writing CC2530/CC2531 skip bootloader payload 2023-09-20T20:21:55.775Z zigbee-herdsman:adapter:zStack:unpi:writer --> buffer [239] 2023-09-20T20:21:56.776Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2023-09-20T20:21:56.777Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2023-09-20T20:21:57.029Z zigbee-herdsman:adapter:zStack:znp:log Skip bootloader for CC2652/CC1352 2023-09-20T20:21:57.486Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2023-09-20T20:21:57.487Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2023-09-20T20:21:59.800Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,6,65,128,0,2,1,2,7,1,192] 2023-09-20T20:21:59.800Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,6,65,128,0,2,1,2,7,1,192] 2023-09-20T20:21:59.801Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 6 - 2 - 1 - 128 - [0,2,1,2,7,1] - 192 2023-09-20T20:21:59.802Z zigbee-herdsman:adapter:zStack:znp:AREQ <-- SYS - resetInd - {"reason":0,"transportrev":2,"productid":1,"majorrel":2,"minorrel":7,"hwrev":1} 2023-09-20T20:21:59.803Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.488Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - ping - {"capabilities":1} 2023-09-20T20:22:03.489Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,1,32] 2023-09-20T20:22:03.492Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,1,89,6,61] 2023-09-20T20:22:03.492Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,1,89,6,61] 2023-09-20T20:22:03.492Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 1 - [89,6] - 61 2023-09-20T20:22:03.492Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - ping - {"capabilities":1625} 2023-09-20T20:22:03.493Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.493Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - version - {} 2023-09-20T20:22:03.493Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,2,35] 2023-09-20T20:22:03.496Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,10,97,2,2,1,2,7,1,107,177,52,1,0,129] 2023-09-20T20:22:03.496Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,10,97,2,2,1,2,7,1,107,177,52,1,0,129] 2023-09-20T20:22:03.496Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 10 - 3 - 1 - 2 - [2,1,2,7,1,107,177,52,1,0] - 129 2023-09-20T20:22:03.497Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - version - {"transportrev":2,"product":1,"majorrel":2,"minorrel":7,"maintrel":1,"revision":20230507} 2023-09-20T20:22:03.497Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.497Z zigbee-herdsman:adapter:zStack:adapter Adapter concurrent: 16 2023-09-20T20:22:03.497Z zigbee-herdsman:adapter:zStack:adapter Detected znp version 'zStack3x0' ({"transportrev":2,"product":1,"majorrel":2,"minorrel":7,"maintrel":1,"revision":20230507}) 2023-09-20T20:22:03.498Z zigbee-herdsman:adapter:zStack:startup beginning znp startup 2023-09-20T20:22:03.499Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - getExtAddr - {} 2023-09-20T20:22:03.499Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,33,4,37] 2023-09-20T20:22:03.502Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,8,97,4,139,7,126,37,0,75,18,0,227] 2023-09-20T20:22:03.502Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,8,97,4,139,7,126,37,0,75,18,0,227] 2023-09-20T20:22:03.502Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 8 - 3 - 1 - 4 - [139,7,126,37,0,75,18,0] - 227 2023-09-20T20:22:03.503Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - getExtAddr - {"extaddress":"0x00124b00257e078b"} 2023-09-20T20:22:03.503Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.503Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":130} 2023-09-20T20:22:03.504Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,130,0,178] 2023-09-20T20:22:03.508Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,24,0,104] 2023-09-20T20:22:03.508Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,24,0,104] 2023-09-20T20:22:03.508Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [24,0] - 104 2023-09-20T20:22:03.508Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":24} 2023-09-20T20:22:03.508Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.509Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":130,"offset":0} 2023-09-20T20:22:03.509Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,130,0,0,0,187] 2023-09-20T20:22:03.516Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,26,97,28,0,24,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,1,0,32,229,66,220,3,37] 2023-09-20T20:22:03.516Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,26,97,28,0,24,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,1,0,32,229,66,220,3,37] 2023-09-20T20:22:03.516Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 26 - 3 - 1 - 28 - [0,24,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,1,0,32,229,66,220,3] - 37 2023-09-20T20:22:03.517Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":24,"value":{"type":"Buffer","data":[0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,1,0,32,229,66,220,3]}} 2023-09-20T20:22:03.517Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.518Z zigbee-herdsman:adapter:zStack:startup:strategy determining znp startup strategy 2023-09-20T20:22:03.519Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":96} 2023-09-20T20:22:03.519Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,96,0,80] 2023-09-20T20:22:03.526Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,1,0,113] 2023-09-20T20:22:03.527Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,1,0,113] 2023-09-20T20:22:03.527Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [1,0] - 113 2023-09-20T20:22:03.527Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":1} 2023-09-20T20:22:03.527Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.527Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":96,"offset":0} 2023-09-20T20:22:03.528Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,96,0,0,0,89] 2023-09-20T20:22:03.541Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,3,97,28,0,1,85,42] 2023-09-20T20:22:03.541Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,3,97,28,0,1,85,42] 2023-09-20T20:22:03.541Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 3 - 3 - 1 - 28 - [0,1,85] - 42 2023-09-20T20:22:03.541Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":1,"value":{"type":"Buffer","data":[85]}} 2023-09-20T20:22:03.542Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.544Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":33} 2023-09-20T20:22:03.544Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,33,0,17] 2023-09-20T20:22:03.551Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,116,0,4] 2023-09-20T20:22:03.552Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,116,0,4] 2023-09-20T20:22:03.552Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [116,0] - 4 2023-09-20T20:22:03.552Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":116} 2023-09-20T20:22:03.552Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.552Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":33,"offset":0} 2023-09-20T20:22:03.553Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,33,0,0,0,24] 2023-09-20T20:22:03.576Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,118,97,28,0,116,26,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,98,26,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,139,7,126,37,0,75,18,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,120,10,1,0,0,0,102,10,0,0,236] 2023-09-20T20:22:03.576Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,118,97,28,0,116,26,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,98,26,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,139,7,126,37,0,75,18,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,120,10,1,0,0,0,102,10,0,0,236] 2023-09-20T20:22:03.576Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 118 - 3 - 1 - 28 - [0,116,26,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,98,26,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,139,7,126,37,0,75,18,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,120,10,1,0,0,0,102,10,0,0] - 236 2023-09-20T20:22:03.576Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":116,"value":{"type":"Buffer","data":[26,5,2,51,15,51,0,30,0,0,0,1,5,1,143,0,8,0,2,13,254,0,0,0,11,0,0,0,0,0,0,0,0,0,0,0,98,26,8,0,0,8,0,0,15,15,4,0,1,0,0,0,1,0,0,0,0,139,7,126,37,0,75,18,0,1,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,15,5,0,1,120,10,1,0,0,0,102,10,0,0]}} 2023-09-20T20:22:03.577Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.580Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":98} 2023-09-20T20:22:03.580Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,98,0,82] 2023-09-20T20:22:03.588Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,16,0,96] 2023-09-20T20:22:03.588Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,16,0,96] 2023-09-20T20:22:03.588Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [16,0] - 96 2023-09-20T20:22:03.588Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":16} 2023-09-20T20:22:03.589Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.589Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":98,"offset":0} 2023-09-20T20:22:03.589Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,98,0,0,0,91] 2023-09-20T20:22:03.605Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,18,97,28,0,16,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-20T20:22:03.605Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,18,97,28,0,16,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-20T20:22:03.605Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 18 - 3 - 1 - 28 - [0,16,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13] - 124 2023-09-20T20:22:03.606Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":16,"value":{"type":"Buffer","data":[1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]}} 2023-09-20T20:22:03.606Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.607Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":58} 2023-09-20T20:22:03.607Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,58,0,10] 2023-09-20T20:22:03.616Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,17,0,97] 2023-09-20T20:22:03.616Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,17,0,97] 2023-09-20T20:22:03.616Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [17,0] - 97 2023-09-20T20:22:03.616Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":17} 2023-09-20T20:22:03.616Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.616Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":58,"offset":0} 2023-09-20T20:22:03.617Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,58,0,0,0,3] 2023-09-20T20:22:03.633Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,19,97,28,0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-20T20:22:03.633Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,19,97,28,0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-20T20:22:03.633Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 19 - 3 - 1 - 28 - [0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13] - 124 2023-09-20T20:22:03.633Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":17,"value":{"type":"Buffer","data":[0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]}} 2023-09-20T20:22:03.633Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.634Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvLength - {"id":59} 2023-09-20T20:22:03.634Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,33,19,59,0,11] 2023-09-20T20:22:03.643Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,2,97,19,17,0,97] 2023-09-20T20:22:03.643Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,2,97,19,17,0,97] 2023-09-20T20:22:03.643Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 2 - 3 - 1 - 19 - [17,0] - 97 2023-09-20T20:22:03.643Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvLength - {"length":17} 2023-09-20T20:22:03.643Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.643Z zigbee-herdsman:adapter:zStack:znp:SREQ --> SYS - osalNvReadExt - {"id":59,"offset":0} 2023-09-20T20:22:03.644Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,4,33,28,59,0,0,0,2] 2023-09-20T20:22:03.660Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,19,97,28,0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-20T20:22:03.660Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,19,97,28,0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13,124] 2023-09-20T20:22:03.660Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 19 - 3 - 1 - 28 - [0,17,0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13] - 124 2023-09-20T20:22:03.661Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- SYS - osalNvReadExt - {"status":0,"len":17,"value":{"type":"Buffer","data":[0,1,3,5,7,9,11,13,15,0,2,4,6,8,10,12,13]}} 2023-09-20T20:22:03.661Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.669Z zigbee-herdsman:adapter:zStack:startup:strategy (stage-1) adapter is configured 2023-09-20T20:22:03.669Z zigbee-herdsman:adapter:zStack:startup:strategy (stage-2) adapter state matches configuration 2023-09-20T20:22:03.670Z zigbee-herdsman:adapter:zStack:startup determined startup strategy: startup 2023-09-20T20:22:03.670Z zigbee-herdsman:adapter:zStack:znp:SREQ --> UTIL - getDeviceInfo - {} 2023-09-20T20:22:03.670Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,0,39,0,39] 2023-09-20T20:22:03.679Z zigbee-herdsman:adapter:zStack:unpi:parser <-- [254,14,103,0,0,139,7,126,37,0,75,18,0,254,255,7,0,0,225] 2023-09-20T20:22:03.679Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [254,14,103,0,0,139,7,126,37,0,75,18,0,254,255,7,0,0,225] 2023-09-20T20:22:03.679Z zigbee-herdsman:adapter:zStack:unpi:parser --> parsed 14 - 3 - 7 - 0 - [0,139,7,126,37,0,75,18,0,254,255,7,0,0] - 225 2023-09-20T20:22:03.680Z zigbee-herdsman:adapter:zStack:znp:SRSP <-- UTIL - getDeviceInfo - {"status":0,"ieeeaddr":"0x00124b00257e078b","shortaddr":65534,"devicetype":7,"devicestate":0,"numassocdevices":0,"assocdeviceslist":[]} 2023-09-20T20:22:03.680Z zigbee-herdsman:adapter:zStack:unpi:parser --- parseNext [] 2023-09-20T20:22:03.681Z zigbee-herdsman:adapter:zStack:startup starting adapter as coordinator 2023-09-20T20:22:03.681Z zigbee-herdsman:adapter:zStack:znp:SREQ --> ZDO - startupFromApp - {"startdelay":100} 2023-09-20T20:22:03.681Z zigbee-herdsman:adapter:zStack:unpi:writer --> frame [254,2,37,64,100,0,3] ```

UPDATE: Again, after about 1 hour, Z2M rebooted successfully.

thargy commented 1 year ago

OK, I updated to 20230901 to see if that improved things. The first start of the addon caused the same error, but, as with the last time I updated the firmware, it succeeded on the second attempt.

thargy commented 1 year ago

So, a reboot after about 2 hours caused it to go back into the failed state. After multiple unsuccessful reboot attempts, I again reflashed the firmware and restored the network backup. However, this time, it failed to reboot after multiple attempts, so the 'pattern' of succeeding on the 2nd attempt after a flash was a coincidence and probably more related to time passing.

I've set the HAOS addon watchdog back on so that it repeatedly attempts a reboot, to see if it eventually succeeds and will update this comment.

UPDATE: Nope, it didn't restart, so I reflashed again, and still no luck :(

Koenkk commented 1 year ago

Could it be that there are 2 zigbee networks in your house?

thargy commented 1 year ago

Could it be that there are 2 zigbee networks in your house?

Yes, as I mentioned in the description:

I've been running two instances of Z2m for about six months on two separate machines (an Intel NUC as a HAOS addon and a Rasberry Pi as a standalone Z2m instance) to allow me to run with two separate channels.

The primary network runs on channel 11 and has 159 devices. Z2m runs as a Home Assistant Add-on on an Intel NUC. The secondary network runs on channel 12 and has 17 'noisy' sensors. Z2m runs directly on a Rasberry Pi as the only service.

I split the networks due to the issues caused by the 17 'noisy' presence sensors that made it unstable. It has been relatively stable for about four months with this setup.

I also have a Philips Hue bridge with a few lights attached (about 4 or 5). I don't know what channel it runs on, but it's coordinator is on the other side of the house.

They added a 'smart' meter to my electricity supply about a month ago. However, it doesn't work due to an inability to sync to the radio network. As such, I haven't set up the monitor. It too, uses Zigbee, but I don't believe it is active.

thargy commented 1 year ago

Z2m booted up again after about 9 hours this morning, and has been running since, though only 100 of 159 devices are 'online'. I have ordered some new coordinators as backups, and am crossing my fingers I can keep the network up in the meantime. Do you have any suggestions as to why it timeouts at this point?

Koenkk commented 1 year ago

I suggest to downgrade to 20221226 (https://github.com/Koenkk/Z-Stack-firmware/tree/Z-Stack_3.x.0_coordinator_20221226/coordinator/Z-Stack_3.x.0/bin), problems have been reported with 20230507: https://github.com/Koenkk/Z-Stack-firmware/discussions/474

thargy commented 1 year ago

I suggest to downgrade to 20221226

Yeah, sorry, being Autistic I'm overly verbose, so I don't blame you for not reading all the walls of text. I just wanted to give you all the info.

You'll see from the details on the first comment, that the problems started whilst it wa running 20221226.

I am running 20230507 on the second coordinator (which isn't showing this issue). I've never run it on the primary.

I upgraded the primary to 20230901 as that's effectively the same as 20221226 just a newer SDK.

The symptom has been the same on both 20221226 and 20230901. I've included logs showing the failure on both versions.

Hope that clears things up.

Koenkk commented 1 year ago

If I recall correctly, startupFromApp can hang when there are conflicting networks. To test if this is the case, can you try wrapping the adapter in thin foil and try to start it?

thargy commented 1 year ago

If I recall correctly, startupFromApp can hang when there are conflicting networks. To test if this is the case, can you try wrapping the adapter in thin foil and try to start it?

So wrapping the adapter in tin toil, and removing the antennae allows Z2M to start, but all communications to devices fail with failed (SRSP - AF - dataRequestExt after 6000ms)', so it doesn't get me anywhere, except suggest a conflicting network. That's strange as it's been stable for months, but it is channel 11 which is the most commonly used I suppose.

The prospect of changing to Channel 25 and repairing 150+ devices is more than a little daunting, especially as the vast majority are Philips hue bulbs, and they would require unpairing first... which would be a challenge. Some of the lights are in very inaccessible places too.

So, I then replaced my Sonoff Dongle with a new one straight from the box and flashed with 20221226 and the network backup. It too failed to start with Error: SRSP - ZDO - startupFromApp after 40000ms - effectively ruling out bad NVRAM, or a faulty device.

The real issue is how to identify the culprit that's stomping on my zigbee channel...

thargy commented 1 year ago

So, I unplugged my Philips Hue hub (which is 2 floors away) and the second coordinator (which is supposed to be on Channel 12). I can't physically disconnect the Smart Meter, but it's in the garage and has no devices connected to it. I can't disconnect my Google Wifi Pro 6 (which was the worst purchase decision ever btw) and I can't see what channel it's running on, never mind change it (because it's SH*T), but I would expect Channel 12 to be stomped on too if the issue was Wifi related.

None of these steps made any difference.

I am running the coordinator on a USB extension cord already, and, as mentioned, it's been relatively stable until 3 days ago.

thargy commented 1 year ago

Not hardware fault - I have now swapped USB wires, ports, and coordinator hardware and confirmed the issue remains exclusive to the primary network, and not the secondary network.
Not Wifi - Further, as the secondary network is Channel 12, and the primary is on Channel 11, it is unlikely that Wifi is causing the issue (as it would stomp over 12 even more than 11).
Unlikely to be other Zigbee network - I'm in quite a remote location and my only neighbour barely has wifi. As such a competing network is unlikely.
Likely to be too many devices/a device on network - However, after 18 hours of being unable to start Z2M I switched off all my light circuits and rebooted, this time Z2M started straight away. I could then bring up each light circuit separately and wait to stabilize (which is what I'm in the process of doing now).

So my working theory is one of:

There is a device(s) on my network that does something when the coordinator initially starts that causes the startup to fail.
The coordinator does not handle starting in a large network well.

I haven't got a sniffer, many of the CC2531 modules I can see require a separate programmer board that I'm not sure how to source or use.

UPDATE: So I set availability timeout to a week and started forcing devices to connect by requesting state from them. After ~100 devices, I started getting the infamous: failed (SREQ '--> ZDO - extRouteDisc - {"dstAddr":36474,"options":0,"radius":30}' failed with status '(0xc7: NWK_TABLE_FULL)' (expected '(0x00: SUCCESS)'))).

After a further 10 minutes, I started getting: failed (SRSP - AF - dataRequest after 6000ms)) and the network crashed.

Koenkk commented 1 year ago

Since it is starting now but the coordinator is crashing, can you try 20221226 again? (it's seems to be the most stable fw for now based on the feedback of many users)

thargy commented 1 year ago

Since it is starting now but the coordinator is crashing, can you try 20221226 again? (it's seems to be the most stable fw for now based on the feedback of many users)

I'm not sure what that helps demonstrate? As I've already stated, the problems started when I was on 20221226 already (and had been for about six months. However, I did as asked and, sure enough, it wouldn't start up again at all, until I switched off all my light circuits (unpowering about 130 devices). However, switching on the circuits after a reboot almost immediately caused the dreaded failed (SRSP - AF - dataRequest after 6000ms)) to start - i.e.

[20:35:00] INFO: Preparing to start...
[20:35:00] INFO: Socat not enabled
[20:35:00] INFO: Starting Zigbee2MQTT...
Zigbee2MQTT:warn  2023-09-23 20:35:45: Failed to ping 'Balcony Spot 2' (attempt 1/1, Read 0x001788010cf4f4cb/11 genBasic(["zclVersion"], {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Data request failed with error: 'No network route' (205)))
Zigbee2MQTT:warn  2023-09-23 20:35:50: Failed to ping 'Garage Switch Right' (attempt 1/1, Read 0x54ef4410005c8290/1 genBasic(["zclVersion"], {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Data request failed with error: 'No network route' (205)))
Zigbee2MQTT:warn  2023-09-23 20:35:57: Failed to ping 'Bedroom 1 Spot 2' (attempt 1/1, Read 0x001788010cf2df14/11 genBasic(["zclVersion"], {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Data request failed with error: 'No network route' (205)))
Zigbee2MQTT:error 2023-09-23 20:36:07: Publish 'set' 'brightness' to 'Kitchen Spots' failed: 'Error: Command 22 genLevelCtrl.moveToLevelWithOnOff({"level":163,"transtime":10}) failed (SRSP - AF - dataRequestExt after 6000ms)'
Zigbee2MQTT:warn  2023-09-23 20:36:13: Failed to ping 'Bedroom 1 Spot 4' (attempt 1/1, Read 0x001788010cf6d54b/11 genBasic(["zclVersion"], {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (SRSP - AF - dataRequest after 6000ms))
Zigbee2MQTT:error 2023-09-23 20:36:19: Publish 'set' 'color_temp' to 'Kitchen Spots' failed: 'Error: Command 22 lightingColorCtrl.moveToColorTemp({"colortemp":400,"transtime":10}) failed (SRSP - AF - dataRequestExt after 6000ms)'
Zigbee2MQTT:warn  2023-09-23 20:36:25: Failed to ping 'Bedroom 1 Spot 5' (attempt 1/1, Read 0x001788010cf2d2db/11 genBasic(["zclVersion"], {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (SRSP - AF - dataRequest after 6000ms))
Zigbee2MQTT:warn  2023-09-23 20:36:36: Failed to ping 'Bedroom 1 Spot 6' (attempt 1/1, Read 0x001788010cf6c741/11 genBasic(["zclVersion"], {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (SRSP - AF - dataRequest after 6000ms))
Zigbee2MQTT:warn  2023-09-23 20:36:47: Failed to ping 'Bedroom 1 Spot 7' (attempt 1/1, Read 0x001788010cf69b23/11 genBasic(["zclVersion"], {"sendWhen":"immediate","timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (SRSP - AF - dataRequest after 6000ms))

UPDATE: To be uber-complete, I have also downgraded my secondary network coordinator to 2022126, as I have been running 20230507 successfully for the last few months. Unsurprisingly, it had no impact and Z2m on the primary coordinator doesn't start up even when both are running 20221226. I have now run every combination of coordinators in 20221226, 20230509 and 20230901, and the result is identical.

The only way I can get the network to start up reliably is to switch off all the lights. That takes out about 100 of the 150+ zigbee devices. I can then add back one floor (which adds back about 60+ devices, but I get a lot of NWK_TABLE_FULL, the occasional AF - datarequest and even one MAC no ack.

The vast majority of my lights are Philips Hue spots, which are usually rock solid. I haven't done any recent updates to bring on this new turn events.

UPDATE 2: I managed to get the network to about 133 devices, but slowly switching on rooms one at a time until all the lights pinged. I occasionally got a few AF - datarequest but the network settled down. I tried going past that to 153 devices, but it died, so, for now, I've stopped at 133 to see if it settles for a bit. When I re-wired the house and lights, I placed master room switches in the plant room to allow me to switch off power to lights in a single room (in case I get lights stuck on and want to go to bed!). Manually nursing the reboot like this takes considerable time and still doesn't appear to be bomb-proof. I'm unsure why the network has suddenly become less stable after being relatively OK for the last few months.

UPDATE 3: After being stable overnight I tried to add the final ~15 devices, using the same room-by-room method, and I quickly hit the AF - datarequest timeouts and the network stopped responding. So, even this approach doesn't get me back to where I was a week ago :(

thargy commented 1 year ago

After a few more days of testing, I identified a couple of Moes Thermostats that are super chatty and moved them to my secondary network. This improved things slighty, but I'm still having the same problems getting the network to start.

What I'm seeing is that, when busy, Z2M continues to send messages into an already busy environment, which causes a cascade failure, resulting in BUFFER_FULL, timeouts (AF), etc. This is particularly the case when the network is starting up. Sometimes, the coordinator can slowly recover from this state, but usually, it is fatal.

Because of this, particularly chatty devices, like sensors, are problematic. Also, the number of pings and messages being spammed by Z2M on startup (like querying the device state when it first sees the device on startup) contributes to the issue of starting up stably in a large network environment.

I've started looking through the code base to see if there's any throttling ability built into sending messages to the coordinator based on the current frames/second. I suspect such a feature would be really useful and lead to a much more stable coordinator in busy environments.

What would be good is for the herdsman to track the current reception and transmission rate (preferably in kb/s, but even msg/s would be useful). Exposing these two figures would be useful for debugging.

With these two rates, it would then be good to update the waitress to delay sending messages until the combined rate is below a configurable threshold. This would reduce pressure on the coordinator and prevent contributing to the saturated network environment. It is better for the message to timeout higher up the stack than on the network itself.

As a final stage, adding a priority to message types would allow messages such as pings, OTA updates, etc., to be placed at a lower priority. Also, splitting the timeout into two - the timeout after the initial send (when the waitress receives the message) and the timeout after the actual transmit (when it releases it to the coordinator after the network saturation is deemed low enough) would allow messages such as availability pings to be given a low priority but a longer send timeout whilst keeping the transmit timeout short.

Later, Z2M itself could use the network saturation data to determine optimum times to do maintenance work (like querying initial state, pinging availability, etc.), helping to balance the network load.

What do you think as a way forward to support larger networks?

TL;DR I propose adding the following features (in order):

Report transmit and receive rates (expose via UI, MQTT, logs).
Allow configuration of a maximum network saturation (based on combined transmit & receive rate), and update waitress only to send messages whilst the network is below the configured rate.
Add message priorities and update the waitress to send messages based on priority (now that it can delay sending a message to the coordinator based on network saturation).
Split timeouts into timeout from initial send, which should be greater than or equal to timeout from transmit. This allows low-priority messages to sit in the waitress queue for longer without hitting their timeout.
Utilise network saturation data within Z2M to create more advanced strategies around availability and state checking to help reduce network load.

Koenkk commented 1 year ago

You can configure the amount of concurrent messages, see https://www.zigbee2mqtt.io/guide/configuration/adapter-settings.html#mdns-zeroconf-discovery

thargy commented 1 year ago

I'll try reducing to 8 as that is half the recommended value, and see what happens.

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

WhistleMaster commented 7 months ago

I have a similar issue https://github.com/Koenkk/zigbee2mqtt/issues/21962. Did you figure out what the problem was ? Thanks !

Koenkk / zigbee-herdsman