zigbee-herdsman: Sudden failure to startup - timeout after SRSP - ZDO - startupFromApp

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
Property Value
Hardware Beelink EQ12 Pro Intel 12th N305
RAM 16G (DDR5)
Zigbee2MQTT version 1.33.0-1
Coordinator Sonoff Zigbee 3.0 USB Dongle Plus
Coordinator Chip CC2652P
Coordinator type zStack3x0
Coordinator revision 20221226
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)

About this issue

  • Original URL
  • State: closed
  • Created 9 months ago
  • Comments: 20 (6 by maintainers)

Most upvoted comments

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

+1
Koenkk on Sep 26, 2023

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 😦

+1
thargy on Sep 24, 2023
Read more comments on GitHub
← zigbee-herdsman: Possible routing issue(?): Timeout - 57587 - 1 - 246 - 513 - 4 after 10000ms
zigbee-herdsman: Unhandled promise rejection when stopping the coordinator →