SLZB-06M, ember driver, z2m doesn't start

What happened?

I decided to switch to ember driver on my SLZB-06M. I flashed firmware via OTA (20240510 ). Unfortunately Zigbee2MQTT fails to start... I have checked different baud rates but without success. With ezsp driver works, but with errors.

What did you expect to happen?

No response

How to reproduce it (minimal and precise)

port: tcp://10.10.10.245:6638 baudrate: 115200 adapter: ember rtscts: false

Zigbee2MQTT version

1.38.0-1

Adapter firmware version

7.4.1.0 build 0

Adapter

ember

Setup

Add-on on Home Assistant OS on RPI4

Debug log

[10:09:27] INFO: Preparing to start... [10:09:28] INFO: Socat not enabled [10:09:30] INFO: Starting Zigbee2MQTT... [2024-06-21 10:09:36] error: zh:ember:uart:ash: Received frame with CRC error [2024-06-21 10:09:36] error: zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT. [2024-06-21 10:09:36] error: zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR [2024-06-21 10:09:36] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR. [2024-06-21 10:09:38] warning: zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e] [2024-06-21 10:09:38] error: zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE. [2024-06-21 10:09:38] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR [2024-06-21 10:09:38] error: zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR. [2024-06-21 10:09:38] error: zh:ember: !!! NCP FATAL ERROR reason=HOST_FATAL_ERROR. ATTEMPTING RESET... !!! [2024-06-21 10:14:37] error: z2m:mqtt: Not connected to MQTT server! [2024-06-21 10:14:37] error: z2m:mqtt: Cannot send message: topic: 'zigbee2mqtt/bridge/state', payload: '{"state":"offline"} [10:14:38] INFO: Preparing to start... [10:14:39] INFO: Socat not enabled [10:14:41] INFO: Starting Zigbee2MQTT... [2024-06-21 10:14:47] warning: zh:ezsp: Deprecated driver 'ezsp' currently in use, 'ember' will become the officially supported EmberZNet driver in next release. If using Zigbee2MQTT see https://github.com/Koenkk/zigbee2mqtt/discussions/21462 [2024-06-21 10:14:47] error: zh:ezsp:uart: <-- CRC error: 5593499cc3af15c6d19874f0cf3488fce23ea5ebc9de6fa220c3e6e27e|e6e2|8816 [2024-06-21 10:14:47] error: zh:ezsp:uart: Error while parsing to NpiFrame 'Error: <-- CRC error: 5593499cc3af15c6d19874f0cf3488fce23ea5ebc9de6fa220c3e6e27e|e6e2|8816 at Frame.checkCRC (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/frame.ts:87:19) at SerialDriver.onParsed (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/uart.ts:169:19) at Parser.emit (node:events:517:28) at Parser._transform (/app/node_modules/zigbee-herdsman/src/adapter/ezsp/driver/parser.ts:49:26) at Parser.Transform._write (node:internal/streams/transform:175:8) at writeOrBuffer (node:internal/streams/writable:392:12) at _write (node:internal/streams/writable:333:10) at Parser.Writable.write (node:internal/streams/writable:337:10) at Socket.ondata (node:internal/streams/readable:809:22) at Socket.emit (node:events:517:28)'

Can you solve the MQTT issue first (Not connected to MQTT server!), then provide a debug log?

I think the MQTT problem message is related to fact, that z2m not starting correctly. When the adapter is set to ember frontent it also does not work (bad gateway). After switching to ezsp, everything works (both frontend and mqtt).

below debug: log.log

Following- similar issue

Can you confirm what devices are these (link to the docs pages would be great):

3662 (0x0E4E)
7979 (0x1F2B)

From your log, these two sent nearly 1500 messages in under 2 minutes, before Z2M even finished starting properly. Something's definitely wrong/bad there. ember starts fine, but these two seem to mess with the end of the Z2M starting process with their spamming. Can you try powering these two off (unplug, remove battery), then starting Z2M, to confirm?

here you are :)

those two devices are electricity meters https://www.zigbee2mqtt.io/devices/SPM01.html#tuya-spm01

I have disabled them and got logs. The same symptoms :/ both frontend and zigbee network didn't work...

log.log

ok, I have solved problem :) In my case if log level is set to warning and in the same time adapter is set to ember z2m doesn't start (bad gateway). I case of ezsp frontend works. The solution is to set log level to warn. In both cases frontent works. It's very strange...

Did you modify anything else? Since you provided a log with debug, it seems strange that log level warning/warn would be the problem.

ok, you are right log level is dead end. I restarted addon and again both frontend and z2m didn't work. So, I decided to start form scratch - what I did:

removed addon
removed zigbee2mqtt folder
installed addon (ember driver) and repaired above thirty devices
restarted addon and again (bad gateway).
I made couple of test with different log levels but without success
switched to ezsp and everything work without errors log-warn(ember).log log-info(ember).log log-debug(ember).log

I had same issues when switching from ezsp to ember. It appears HomeAssistant caches the settings so it did NOT reflect that I edited the configuration.yaml manually via ssh+vim. I also had to delete the json and database files in that folder, leaving just the configuration.yaml and reboot.

My impression from the logs was that one cannot switch properly from one driver to the other. What really s*cks that the config values shown via HA web GUI do not reflect the actual content of the /config/zigbee2mqtt_"$somenumber"/configuration.yaml.

@mmokrejs If the file and the UI are "synced", it shouldn't be a problem, but yeah, some operations break that link and the UI no longer reflects the content properly (like switching from regular to edge or vice versa). Otherwise, switching from one driver to the other is just a matter of changing the adapter config. I don't think this is the same issue though, as @Herreropl redid the whole setup and still has the problem.

@Herreropl Seems to be indeed something with those devices that start spamming very early (0xF738 this time) and Z2M not finishing its startup sequence for some reason. @Koenkk any ideas? It seems to be stopping right after Herdsman is done (like the start function of the adapter is never actually returning even though it reached the end...). It stops after this, so, basically, here but never gets here, it never does the rest of the logic, so it eventually fails as soon as something calls code that hasn't been setup (MQTT here).

[2024-06-24 00:01:21] info:     zh:ember:queue: Request dispatching started.
...
[2024-06-24 00:02:29] error:    z2m:mqtt: Not connected to MQTT server!
[2024-06-24 00:02:29] error:    z2m:mqtt: Cannot send message: topic: 'zigbee2mqtt/bridge/state', payload: 'offline

@voc0der Looks like your issue might be related to this one. Any chance you can provide a log with debug to confirm after what step it causes trouble?

Here's what happens to me:

On a docker stop/start, update, reboot, etc... it has a 50/50 chance to start in this failed state. I can't tell if it's failing because it can't connect to Mosquito (same host, compose), but I doubt it, because Mosquito says its healthy, zwave works fine, Mosquito has a healthcheck that's well defined, and I've also had it wait 20 seconds just to see, and this error can happen when Mosquito has been running for a long time.

Using '/app/data' as data directory
[2024-06-26 09:19:13] error:    zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=RESET_WATCHDOG.
[2024-06-26 09:19:13] error:    zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR
[2024-06-26 09:19:13] error:    zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-06-26 09:19:15] error:    zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE.
[2024-06-26 09:19:15] error:    zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR
[2024-06-26 09:19:15] error:    zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR.
[2024-06-26 09:19:15] error:    zh:ember: !!! NCP FATAL ERROR reason=HOST_FATAL_ERROR. ATTEMPTING RESET... !!!
[2024-06-26 09:19:15] error:    zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR.
[2024-06-26 09:19:35] error:    z2m:mqtt: Not connected to MQTT server!
[2024-06-26 09:19:35] error:    z2m:mqtt: Cannot send message: topic: 'zigbee2mqtt/bridge/state', payload: '{"state":"offline"}

And here (after I issue docker restart zigbee2mqtt) the error is gone, and it's working:

Using '/app/data' as data directory

I am using the provided extension USB cable to prevent RF interference with the SkyConnect Blue, 7.4.3.0.
It's located in a decently separated area, and not far from some of the nodes (10 feet from its first Hue).
My map looks just fine too unlike reported in the other thread. (45+ hue bulbs and some switches)

This might not be the right thread for my issue as well, I'm now realizing.

@Nerivec thanks for getting me to the right thread. Here it is. This is the 'failed' state of it not starting properly.

Logs

``` Using '/app/data' as data directory [2024-06-26 11:13:38] info: z2m: Logging to console, file (filename: log.log) [2024-06-26 11:13:38] debug: z2m: Loaded state from file /app/data/state.json [2024-06-26 11:13:38] info: z2m: Starting Zigbee2MQTT version 1.38.0 (commit #fe048e6) [2024-06-26 11:13:38] info: z2m: Starting zigbee-herdsman (0.49.2) [2024-06-26 11:13:38] debug: z2m: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backupPath":"/app/data/coordinator_backup.json","databaseBackupPath":"/app/data/database.db.backup","databasePath":"/app/data/database.db","network":{"channelList":[25],"extendedPanID":[222,158,171,2,134,204,14,1],"networkKey":"HIDDEN","panID":28602},"serialPort":{"adapter":"ember","path":"/dev/ttyACM0","rtscts":true}}' [2024-06-26 11:13:38] info: zh:ember: Using default stack config. [2024-06-26 11:13:38] debug: zh:ember: Using delay=5. [2024-06-26 11:13:38] debug: zh:controller: Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[221,75,142,123,205,153,202,191,222,203,211,151,148,58,233,216],"panID":28602,"extendedPanID":[222,158,171,2,134,204,14,1],"channelList":[25]},"serialPort":{"rtscts":true,"path":"/dev/ttyACM0","adapter":"ember"},"databasePath":"/app/data/database.db","databaseBackupPath":"/app/data/database.db.backup","backupPath":"/app/data/coordinator_backup.json","adapter":{"disableLED":false,"concurrent":null,"delay":null}}' [2024-06-26 11:13:38] info: zh:ember: ======== Ember Adapter Starting ======== [2024-06-26 11:13:38] debug: zh:ember: Starting EZSP with stack configuration: "[object Object]". [2024-06-26 11:13:38] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-06-26 11:13:38] info: zh:ember:uart:ash: ======== ASH NCP reset ======== [2024-06-26 11:13:38] debug: zh:ember:uart:ash: Opening serial port with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":true,"autoOpen":false,"parity":"none","stopBits":1,"xon":false,"xoff":false} [2024-06-26 11:13:38] info: zh:ember:uart:ash: Serial port opened [2024-06-26 11:13:38] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-06-26 11:13:38] debug: zh:ember:uart:ash: ---> [FRAME type=RST] [2024-06-26 11:13:38] debug: zh:ember:uart:ash: Waiting for RSTACK... 0/2500 [2024-06-26 11:13:38] debug: zh:ember:uart:ash: Waiting for RSTACK... 100/2500 [2024-06-26 11:13:38] debug: zh:ember:uart:ash: Waiting for RSTACK... 200/2500 [2024-06-26 11:13:38] debug: zh:ember:uart:ash: Waiting for RSTACK... 300/2500 [2024-06-26 11:13:39] debug: zh:ember:uart:ash: <--- [FRAME type=ERROR] [2024-06-26 11:13:39] error: zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=RESET_WATCHDOG. [2024-06-26 11:13:39] error: zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR [2024-06-26 11:13:39] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR. [2024-06-26 11:13:39] info: zh:ember:uart:ash: ======== ASH NCP reset ======== [2024-06-26 11:13:39] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-06-26 11:13:39] debug: zh:ember:uart:ash: ---> [FRAME type=RST] [2024-06-26 11:13:39] debug: zh:ember:uart:ash: Waiting for RSTACK... 0/2500 [2024-06-26 11:13:39] debug: zh:ember:uart:ash: Waiting for RSTACK... 100/2500 [2024-06-26 11:13:39] debug: zh:ember:uart:ash: Waiting for RSTACK... 200/2500 [2024-06-26 11:13:39] debug: zh:ember:uart:ash: Waiting for RSTACK... 300/2500 [2024-06-26 11:13:39] debug: zh:ember:uart:ash: Waiting for RSTACK... 400/2500 [2024-06-26 11:13:39] debug: zh:ember:uart:ash: Waiting for RSTACK... 500/2500 [2024-06-26 11:13:39] debug: zh:ember:uart:ash: Waiting for RSTACK... 600/2500 [2024-06-26 11:13:39] debug: zh:ember:uart:ash: Waiting for RSTACK... 700/2500 [2024-06-26 11:13:39] debug: zh:ember:uart:ash: Waiting for RSTACK... 800/2500 [2024-06-26 11:13:39] debug: zh:ember:uart:ash: Waiting for RSTACK... 900/2500 [2024-06-26 11:13:40] debug: zh:ember:uart:ash: Waiting for RSTACK... 1000/2500 [2024-06-26 11:13:40] debug: zh:ember:uart:ash: <--- [FRAME type=RSTACK] [2024-06-26 11:13:40] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-06-26 11:13:40] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-06-26 11:13:40] info: zh:ember:uart:ash: ======== ASH started ======== [2024-06-26 11:13:40] info: zh:ember:ezsp: ======== EZSP started ======== [2024-06-26 11:13:40] debug: zh:ember:ezsp: ===> [FRAME: ID=0:"VERSION" Seq=0 Len=4] [2024-06-26 11:13:40] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-06-26 11:13:41] warning: zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e] [2024-06-26 11:13:41] debug: zh:ember:uart:ash: <--- [FRAME type=RSTACK] [2024-06-26 11:13:41] error: zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE. [2024-06-26 11:13:41] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR [2024-06-26 11:13:41] error: zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR. [2024-06-26 11:13:41] error: zh:ember: !!! NCP FATAL ERROR reason=HOST_FATAL_ERROR. ATTEMPTING RESET... !!! [2024-06-26 11:13:41] info: zh:ember:queue: Request dispatching stopped; queue=0 priorityQueue=0 [2024-06-26 11:13:41] info: zh:ember:uart:ash: ASH COUNTERS since last clear: [2024-06-26 11:13:41] info: zh:ember:uart:ash: Total frames: RX=2, TX=3 [2024-06-26 11:13:41] info: zh:ember:uart:ash: Cancelled : RX=1, TX=0 [2024-06-26 11:13:41] info: zh:ember:uart:ash: DATA frames : RX=0, TX=1 [2024-06-26 11:13:41] info: zh:ember:uart:ash: DATA bytes : RX=0, TX=4 [2024-06-26 11:13:41] info: zh:ember:uart:ash: Retry frames: RX=0, TX=0 [2024-06-26 11:13:41] info: zh:ember:uart:ash: ACK frames : RX=0, TX=1 [2024-06-26 11:13:41] info: zh:ember:uart:ash: NAK frames : RX=0, TX=0 [2024-06-26 11:13:41] info: zh:ember:uart:ash: nRdy frames : RX=0, TX=0 [2024-06-26 11:13:41] info: zh:ember:uart:ash: CRC errors : RX=0 [2024-06-26 11:13:41] info: zh:ember:uart:ash: Comm errors : RX=0 [2024-06-26 11:13:41] info: zh:ember:uart:ash: Length < minimum: RX=0 [2024-06-26 11:13:41] info: zh:ember:uart:ash: Length > maximum: RX=0 [2024-06-26 11:13:41] info: zh:ember:uart:ash: Bad controls : RX=0 [2024-06-26 11:13:41] info: zh:ember:uart:ash: Bad lengths : RX=0 [2024-06-26 11:13:41] info: zh:ember:uart:ash: Bad ACK numbers : RX=0 [2024-06-26 11:13:41] info: zh:ember:uart:ash: Out of buffers : RX=0 [2024-06-26 11:13:41] info: zh:ember:uart:ash: Retry dupes : RX=0 [2024-06-26 11:13:41] info: zh:ember:uart:ash: Out of sequence : RX=0 [2024-06-26 11:13:41] info: zh:ember:uart:ash: ACK timeouts : RX=0 [2024-06-26 11:13:41] error: zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR. [2024-06-26 11:13:41] info: zh:ember:uart:ash: Port closed. Error? no [2024-06-26 11:13:41] info: zh:ember:uart:ash: ======== ASH stopped ======== [2024-06-26 11:13:41] info: zh:ember:ezsp: ======== EZSP stopped ======== [2024-06-26 11:13:41] info: zh:ember: ======== Ember Adapter Stopped ======== [2024-06-26 11:13:41] info: zh:ember: ======== Ember Adapter Starting ======== [2024-06-26 11:13:41] debug: zh:ember: Starting EZSP with stack configuration: "[object Object]". [2024-06-26 11:13:41] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-06-26 11:13:41] info: zh:ember:uart:ash: ======== ASH NCP reset ======== [2024-06-26 11:13:41] debug: zh:ember:uart:ash: Opening serial port with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":true,"autoOpen":false,"parity":"none","stopBits":1,"xon":false,"xoff":false} [2024-06-26 11:13:41] info: zh:ember:uart:ash: Serial port opened [2024-06-26 11:13:41] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-06-26 11:13:41] debug: zh:ember:uart:ash: ---> [FRAME type=RST] [2024-06-26 11:13:41] debug: zh:ember:uart:ash: Waiting for RSTACK... 0/2500 [2024-06-26 11:13:41] debug: zh:ember:uart:ash: Waiting for RSTACK... 100/2500 [2024-06-26 11:13:41] debug: zh:ember:uart:ash: Waiting for RSTACK... 200/2500 [2024-06-26 11:13:42] debug: zh:ember:uart:ash: Waiting for RSTACK... 300/2500 [2024-06-26 11:13:42] debug: zh:ember:uart:ash: Waiting for RSTACK... 400/2500 [2024-06-26 11:13:42] debug: zh:ember:uart:ash: Waiting for RSTACK... 500/2500 [2024-06-26 11:13:42] debug: zh:ember:uart:ash: Waiting for RSTACK... 600/2500 [2024-06-26 11:13:42] debug: zh:ember:uart:ash: Waiting for RSTACK... 700/2500 [2024-06-26 11:13:42] debug: zh:ember:uart:ash: Waiting for RSTACK... 800/2500 [2024-06-26 11:13:42] debug: zh:ember:uart:ash: Waiting for RSTACK... 900/2500 [2024-06-26 11:13:42] debug: zh:ember:uart:ash: Waiting for RSTACK... 1000/2500 [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=RSTACK] [2024-06-26 11:13:42] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-06-26 11:13:42] info: zh:ember:uart:ash: ======== ASH started ======== [2024-06-26 11:13:42] info: zh:ember:ezsp: ======== EZSP started ======== [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=0:"VERSION" Seq=0 Len=4] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=0:"VERSION" Seq=0 Len=7] [2024-06-26 11:13:42] debug: zh:ember: NCP info: EZSPVersion=13 StackType=2 StackVersion=29744 [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=170:"GET_VALUE" Seq=1 Len=6] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=170:"GET_VALUE" Seq=1 Len=14] [2024-06-26 11:13:42] debug: zh:ember: NCP version info: {"ezsp":13,"revision":"7.4.3 [GA]","build":0,"major":7,"minor":4,"patch":3,"special":0,"type":170} [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=2 Len=8] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=2 Len=6] [2024-06-26 11:13:42] debug: zh:ember: [EzspConfigId] SET "ADDRESS_TABLE_SIZE" TO "16" with status=SUCCESS. [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=3 Len=8] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=3 Len=6] [2024-06-26 11:13:42] debug: zh:ember: [EzspConfigId] SET "TRUST_CENTER_ADDRESS_CACHE_SIZE" TO "2" with status=SUCCESS. [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=4 Len=8] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=4 Len=6] [2024-06-26 11:13:42] debug: zh:ember: [EzspConfigId] SET "INDIRECT_TRANSMISSION_TIMEOUT" TO "7680" with status=SUCCESS. [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=5 Len=8] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=5 Len=6] [2024-06-26 11:13:42] debug: zh:ember: [EzspConfigId] SET "MAX_HOPS" TO "30" with status=SUCCESS. [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=6 Len=8] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=6 Len=6] [2024-06-26 11:13:42] debug: zh:ember: [EzspConfigId] SET "TX_POWER_MODE" TO "32768" with status=SUCCESS. [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=7 Len=8] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=7 Len=6] [2024-06-26 11:13:42] debug: zh:ember: [EzspConfigId] SET "SUPPORTED_NETWORKS" TO "1" with status=SUCCESS. [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=171:"SET_VALUE" Seq=8 Len=8] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=171:"SET_VALUE" Seq=8 Len=6] [2024-06-26 11:13:42] debug: zh:ember: [EzspValueId] SET "END_DEVICE_KEEP_ALIVE_SUPPORT_MODE" TO "3" with status=SUCCESS. [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=9 Len=7] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=9 Len=6] [2024-06-26 11:13:42] debug: zh:ember: [EzspPolicyId] SET "BINDING_MODIFICATION_POLICY" TO "18" with status=SUCCESS. [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=10 Len=7] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=10 Len=6] [2024-06-26 11:13:42] debug: zh:ember: [EzspPolicyId] SET "MESSAGE_CONTENTS_IN_CALLBACK_POLICY" TO "65" with status=SUCCESS. [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=171:"SET_VALUE" Seq=11 Len=9] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=171:"SET_VALUE" Seq=11 Len=6] [2024-06-26 11:13:42] debug: zh:ember: [EzspValueId] SET "MAXIMUM_INCOMING_TRANSFER_SIZE" TO "82,0" with status=SUCCESS. [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=171:"SET_VALUE" Seq=12 Len=9] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=171:"SET_VALUE" Seq=12 Len=6] [2024-06-26 11:13:42] debug: zh:ember: [EzspValueId] SET "MAXIMUM_OUTGOING_TRANSFER_SIZE" TO "82,0" with status=SUCCESS. [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=171:"SET_VALUE" Seq=13 Len=9] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=171:"SET_VALUE" Seq=13 Len=6] [2024-06-26 11:13:42] debug: zh:ember: [EzspValueId] SET "TRANSIENT_DEVICE_TIMEOUT" TO "16,39" with status=SUCCESS. [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=21:"SET_MANUFACTURER_CODE" Seq=14 Len=7] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=21:"SET_MANUFACTURER_CODE" Seq=14 Len=5] [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=15 Len=8] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=15 Len=6] [2024-06-26 11:13:42] debug: zh:ember: [EzspConfigId] SET "STACK_PROFILE" TO "2" with status=SUCCESS. [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=16 Len=8] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=16 Len=6] [2024-06-26 11:13:42] debug: zh:ember: [EzspConfigId] SET "SECURITY_LEVEL" TO "5" with status=SUCCESS. [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=82:"GET_CONFIGURATION_VALUE" Seq=17 Len=6] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=82:"GET_CONFIGURATION_VALUE" Seq=17 Len=8] [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=18 Len=8] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2] Added to rxQueue [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-06-26 11:13:42] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=18 Len=6] [2024-06-26 11:13:42] debug: zh:ember: [EzspConfigId] SET "BINDING_TABLE_SIZE" TO "32" with status=SUCCESS. [2024-06-26 11:13:42] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=19 Len=8] [2024-06-26 11:13:42] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=19 Len=6] [2024-06-26 11:13:43] debug: zh:ember: [EzspConfigId] SET "KEY_TABLE_SIZE" TO "0" with status=SUCCESS. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=20 Len=8] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=20 Len=6] [2024-06-26 11:13:43] debug: zh:ember: [EzspConfigId] SET "MAX_END_DEVICE_CHILDREN" TO "32" with status=SUCCESS. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=21 Len=8] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=21 Len=6] [2024-06-26 11:13:43] debug: zh:ember: [EzspConfigId] SET "APS_UNICAST_MESSAGE_COUNT" TO "32" with status=ERROR_OUT_OF_MEMORY. [2024-06-26 11:13:43] warning: zh:ember: [EzspConfigId] Failed to SET "APS_UNICAST_MESSAGE_COUNT" TO "32" with status=ERROR_OUT_OF_MEMORY. Firmware value will be used instead. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=22 Len=8] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=22 Len=6] [2024-06-26 11:13:43] debug: zh:ember: [EzspConfigId] SET "BROADCAST_TABLE_SIZE" TO "15" with status=SUCCESS. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=23 Len=8] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=23 Len=6] [2024-06-26 11:13:43] debug: zh:ember: [EzspConfigId] SET "NEIGHBOR_TABLE_SIZE" TO "26" with status=SUCCESS. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=24 Len=8] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=24 Len=6] [2024-06-26 11:13:43] debug: zh:ember: [EzspConfigId] SET "END_DEVICE_POLL_TIMEOUT" TO "8" with status=SUCCESS. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=25 Len=8] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=25 Len=6] [2024-06-26 11:13:43] debug: zh:ember: [EzspConfigId] SET "TRANSIENT_KEY_TIMEOUT_S" TO "300" with status=SUCCESS. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=26 Len=8] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=26 Len=6] [2024-06-26 11:13:43] debug: zh:ember: [EzspConfigId] SET "RETRY_QUEUE_SIZE" TO "16" with status=SUCCESS. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=27 Len=8] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=27 Len=6] [2024-06-26 11:13:43] debug: zh:ember: [EzspConfigId] SET "SOURCE_ROUTE_TABLE_SIZE" TO "200" with status=SUCCESS. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=28 Len=8] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=28 Len=6] [2024-06-26 11:13:43] debug: zh:ember: [EzspConfigId] SET "MULTICAST_TABLE_SIZE" TO "16" with status=SUCCESS. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=29 Len=10] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=29 Len=9] [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=2:"ADD_ENDPOINT" Seq=30 Len=63] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=2:"ADD_ENDPOINT" Seq=30 Len=6] [2024-06-26 11:13:43] debug: zh:ember: Registered endpoint "1" with status=SUCCESS. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=31 Len=10] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=31 Len=6] [2024-06-26 11:13:43] debug: zh:ember: Registered multicast table entry: {"multicastId":0,"endpoint":1,"networkIndex":0}. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=32 Len=10] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=32 Len=6] [2024-06-26 11:13:43] debug: zh:ember: Registered multicast table entry: {"multicastId":901,"endpoint":1,"networkIndex":0}. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=33 Len=10] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=33 Len=9] [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=2:"ADD_ENDPOINT" Seq=34 Len=17] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=2:"ADD_ENDPOINT" Seq=34 Len=6] [2024-06-26 11:13:43] debug: zh:ember: Registered endpoint "242" with status=SUCCESS. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=35 Len=10] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=35 Len=6] [2024-06-26 11:13:43] debug: zh:ember: Registered multicast table entry: {"multicastId":2948,"endpoint":242,"networkIndex":0}. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=36 Len=7] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=36 Len=6] [2024-06-26 11:13:43] debug: zh:ember: [EzspPolicyId] SET "TC_KEY_REQUEST_POLICY" TO "81" with status=SUCCESS. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=37 Len=7] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=37 Len=6] [2024-06-26 11:13:43] debug: zh:ember: [EzspPolicyId] SET "APP_KEY_REQUEST_POLICY" TO "96" with status=SUCCESS. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=38 Len=7] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=38 Len=6] [2024-06-26 11:13:43] debug: zh:ember: [EzspPolicyId] SET "TRUST_CENTER_POLICY" TO "3" with status=SUCCESS. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=23:"NETWORK_INIT" Seq=39 Len=7] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=0] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=23:"NETWORK_INIT" Seq=39 Len=6] [2024-06-26 11:13:43] debug: zh:ember: [INIT TC] Network init status=SUCCESS. [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=25:"STACK_STATUS_HANDLER" Seq=39 Len=6] [2024-06-26 11:13:43] debug: zh:ember:ezsp: ezspStackStatusHandler(): callback called with: [status=NETWORK_UP] [2024-06-26 11:13:43] info: zh:ember: [STACK STATUS] Network up. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=40:"GET_NETWORK_PARAMETERS" Seq=40 Len=5] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=1] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=1] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=40:"GET_NETWORK_PARAMETERS" Seq=40 Len=27] [2024-06-26 11:13:43] debug: zh:ember: [INIT TC] Current network config={"networkKeyDistribute":false,"networkKey":[221,75,142,123,205,153,202,191,222,203,211,151,148,58,233,216],"panID":28602,"extendedPanID":[222,158,171,2,134,204,14,1],"channelList":[25]} [2024-06-26 11:13:43] debug: zh:ember: [INIT TC] Current NCP network: nodeType=COORDINATOR params={"extendedPanId":[222,158,171,2,134,204,14,1],"panId":28602,"radioTxPower":5,"radioChannel":25,"joinMethod":0,"nwkManagerId":0,"nwkUpdateId":0,"channels":134215680} [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=276:"EXPORT_KEY" Seq=41 Len=23] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=2] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=2] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=276:"EXPORT_KEY" Seq=41 Len=25] [2024-06-26 11:13:43] debug: zh:ember: [INIT TC] Current NCP network: networkKey=((removed)) [2024-06-26 11:13:43] info: zh:ember: [INIT TC] NCP network matches config. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=16:"SET_CONCENTRATOR" Seq=42 Len=15] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=3] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=3] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=16:"SET_CONCENTRATOR" Seq=42 Len=6] [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=90:"SET_SOURCE_ROUTE_DISCOVERY_MODE" Seq=43 Len=6] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=4] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=4] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=90:"SET_SOURCE_ROUTE_DISCOVERY_MODE" Seq=43 Len=9] [2024-06-26 11:13:43] info: zh:ember: [CONCENTRATOR] Started source route discovery. 1248ms until next broadcast. [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=40:"GET_NETWORK_PARAMETERS" Seq=44 Len=5] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=5] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=5] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=40:"GET_NETWORK_PARAMETERS" Seq=44 Len=27] [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=24:"NETWORK_STATE" Seq=45 Len=5] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=6] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=6] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=24:"NETWORK_STATE" Seq=45 Len=6] [2024-06-26 11:13:43] debug: zh:ember:ezsp: ===> [FRAME: ID=38:"GET_EUI64" Seq=46 Len=5] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=7] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 11:13:43] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=7] Added to rxQueue [2024-06-26 11:13:43] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-06-26 11:13:43] debug: zh:ember:ezsp: <=== [FRAME: ID=38:"GET_EUI64" Seq=46 Len=13] [2024-06-26 11:13:43] debug: zh:ember: [INIT] Network Ready! {"eui64":"0xbc026efffe23387d","parameters":{"extendedPanId":[222,158,171,2,134,204,14,1],"panId":28602,"radioTxPower":5,"radioChannel":25,"joinMethod":0,"nwkManagerId":0,"nwkUpdateId":0,"channels":134215680},"status":2} [2024-06-26 11:13:43] info: zh:ember:queue: Request dispatching started. ```

Looks the same indeed (the retries on startup are just the hardware flow control issues -known to silabs-, only way to get rid of them entirely at the moment is to flash a firmware without hardware flow control -and use rtscts: false-, but it shouldn't be an issue once it starts after that). What is in-between zh:ember:queue: Request dispatching started. and z2m:mqtt: Not connected to MQTT server!?

This following segment repeats. I never see the z2m:mqtt: Not connected to MQTT server! while in debug mode. (I waited 2 minutes, which is as much as I can atm, I'll try more later). I verified the web interface remained offline.

Requested Logs

``` [2024-06-26 13:23:49] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 13:23:49] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 13:23:49] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=0] Added to rxQueue [2024-06-26 13:23:49] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-06-26 13:23:49] debug: zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=46 Len=18] [2024-06-26 13:23:49] debug: zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=63928], [sourceEui=0x001788010db0d593], [lastHopLqi=140], [lastHopRssi=-65], [relayCount=0], [relayList=] [2024-06-26 13:23:49] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 13:23:49] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 13:23:49] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=1] Added to rxQueue [2024-06-26 13:23:49] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-06-26 13:23:49] debug: zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=46 Len=37] [2024-06-26 13:23:49] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":11,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":152}], [lastHopLqi=140], [lastHopRssi=-65], [sender=63928], [bindingIndex=255], [addressIndex=255], [messageContents=01ec01000b10140102240001] [2024-06-26 13:23:59] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 13:23:59] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 13:23:59] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=2] Added to rxQueue [2024-06-26 13:23:59] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-06-26 13:23:59] debug: zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=46 Len=37] [2024-06-26 13:23:59] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":11,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":153}], [lastHopLqi=140], [lastHopRssi=-65], [sender=63928], [bindingIndex=255], [addressIndex=255], [messageContents=01ed01000b10140102240001] [2024-06-26 13:24:09] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 13:24:09] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 13:24:09] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=3] Added to rxQueue [2024-06-26 13:24:09] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-06-26 13:24:09] debug: zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=46 Len=37] [2024-06-26 13:24:09] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":11,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":154}], [lastHopLqi=140], [lastHopRssi=-65], [sender=63928], [bindingIndex=255], [addressIndex=255], [messageContents=01ee01000b10140102240001] [2024-06-26 13:24:19] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 13:24:19] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 13:24:19] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=4] Added to rxQueue [2024-06-26 13:24:19] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-06-26 13:24:19] debug: zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=46 Len=37] [2024-06-26 13:24:19] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":11,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":155}], [lastHopLqi=140], [lastHopRssi=-65], [sender=63928], [bindingIndex=255], [addressIndex=255], [messageContents=01ef01000b10140102240001] [2024-06-26 13:24:21] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 13:24:21] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 13:24:21] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=5] Added to rxQueue [2024-06-26 13:24:21] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-06-26 13:24:21] debug: zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=46 Len=18] [2024-06-26 13:24:21] debug: zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=35006], [sourceEui=0x001788010db0d802], [lastHopLqi=236], [lastHopRssi=-41], [relayCount=0], [relayList=] [2024-06-26 13:24:21] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 13:24:21] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 13:24:21] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-06-26 13:24:21] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-06-26 13:24:21] debug: zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=46 Len=37] [2024-06-26 13:24:21] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":11,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":12}], [lastHopLqi=236], [lastHopRssi=-41], [sender=35006], [bindingIndex=255], [addressIndex=255], [messageContents=017001000b10140102240001] [2024-06-26 13:24:31] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 13:24:31] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 13:24:31] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=7] Added to rxQueue [2024-06-26 13:24:31] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-06-26 13:24:31] debug: zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=46 Len=37] [2024-06-26 13:24:31] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":11,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":13}], [lastHopLqi=236], [lastHopRssi=-41], [sender=35006], [bindingIndex=255], [addressIndex=255], [messageContents=017101000b10140102240001] [2024-06-26 13:24:41] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 13:24:41] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 13:24:41] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=0] Added to rxQueue [2024-06-26 13:24:41] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-06-26 13:24:41] debug: zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=46 Len=37] [2024-06-26 13:24:41] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":11,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":14}], [lastHopLqi=236], [lastHopRssi=-41], [sender=35006], [bindingIndex=255], [addressIndex=255], [messageContents=017201000b10140102240001] [2024-06-26 13:24:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 13:24:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 13:24:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=1] Added to rxQueue [2024-06-26 13:24:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-06-26 13:24:51] debug: zh:ember:ezsp: <=== [FRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=46 Len=18] [2024-06-26 13:24:51] debug: zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=35006], [sourceEui=0x001788010db0d802], [lastHopLqi=236], [lastHopRssi=-41], [relayCount=0], [relayList=] [2024-06-26 13:24:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 13:24:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 13:24:51] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=2] Added to rxQueue [2024-06-26 13:24:51] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-06-26 13:24:51] debug: zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=46 Len=37] [2024-06-26 13:24:51] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":11,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":15}], [lastHopLqi=236], [lastHopRssi=-41], [sender=35006], [bindingIndex=255], [addressIndex=255], [messageContents=017301000b10140102240001] [2024-06-26 13:25:01] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-26 13:25:01] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-26 13:25:01] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=3] Added to rxQueue [2024-06-26 13:25:01] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-06-26 13:25:01] debug: zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=46 Len=37] [2024-06-26 13:25:01] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":11,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":16}], [lastHopLqi=236], [lastHopRssi=-41], [sender=35006], [bindingIndex=255], [addressIndex=255], [messageContents=017401000b10140102240001] ```

I think this message "z2m:mqtt: Not connected to MQTT server!" appears when the addon is going to shutdown or restart. It seems that even frontend is offline something under the hood is working.

Can either of you try the dev branch/edge, see if you get better results?

Same exact results with latest-dev, didn't even make it up on the first docker compose up -d. When I wake up tomorrow I'll try to get logs of that to see if anything is different.

ed (the retries on startup are just the hardware flow control issues -known to silabs-, only way to get rid of them entirely at

I tried this no_hw firmware. After flashing first boot was ok, but after restart the same problem as before :/

[09:35:23] INFO: Preparing to start... [09:35:24] INFO: Socat not enabled [09:35:26] INFO: Starting Zigbee2MQTT... [2024-06-28 09:35:34] warning: zh:ember: [EzspConfigId] Failed to SET "APS_UNICAST_MESSAGE_COUNT" TO "32" with status=ERROR_OUT_OF_MEMORY. Firmware value will be used instead. [2024-06-28 09:35:34] warning: z2m: permit_join set to true in configuration.yaml. [2024-06-28 09:35:34] warning: z2m: Allowing new devices to join. [2024-06-28 09:35:34] warning: z2m: Set permit_join to false once you joined all devices. [09:36:19] INFO: Preparing to start... [09:36:20] INFO: Socat not enabled [09:36:22] INFO: Starting Zigbee2MQTT... [2024-06-28 09:36:29] error: zh:ember:uart:ash: Received frame with CRC error [2024-06-28 09:36:29] error: zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT. [2024-06-28 09:36:29] error: zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR [2024-06-28 09:36:29] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR. [2024-06-28 09:36:31] warning: zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e] [2024-06-28 09:36:31] error: zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE. [2024-06-28 09:36:31] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR [2024-06-28 09:36:31] error: zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR. [2024-06-28 09:36:31] error: zh:ember: !!! NCP FATAL ERROR reason=HOST_FATAL_ERROR. ATTEMPTING RESET... !!! [2024-06-28 09:36:33] warning: zh:ember: [EzspConfigId] Failed to SET "APS_UNICAST_MESSAGE_COUNT" TO "32" with status=ERROR_OUT_OF_MEMORY. Firmware value will be used instead. [2024-06-28 09:37:42] error: z2m:mqtt: Not connected to MQTT server! [2024-06-28 09:37:42] error: z2m:mqtt: Cannot send message: topic: 'zigbee2mqtt/bridge/state', payload: 'offline [09:37:44] INFO: Preparing to start... [09:37:44] INFO: Socat not enabled [09:37:46] INFO: Starting Zigbee2MQTT... [2024-06-28 09:37:52] error: zh:ember:uart:ash: Received frame with CRC error [2024-06-28 09:37:52] error: zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT. [2024-06-28 09:37:52] error: zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR [2024-06-28 09:37:52] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR. [2024-06-28 09:37:55] warning: zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e] [2024-06-28 09:37:55] error: zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE. [2024-06-28 09:37:55] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR [2024-06-28 09:37:55] error: zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR. [2024-06-28 09:37:55] error: zh:ember: !!! NCP FATAL ERROR reason=HOST_FATAL_ERROR. ATTEMPTING RESET... !!! [2024-06-28 09:37:56] warning: zh:ember: [EzspConfigId] Failed to SET "APS_UNICAST_MESSAGE_COUNT" TO "32" with status=ERROR_OUT_OF_MEMORY. Firmware value will be used instead.

Following- similar issue

The no-hw was only for SkyConnect. The 06-m doesn't have hardware flow control, so firmware is the same as you had before. It is unusual to have such a messy startup sequence on it though. Are you on the latest "core firmware" (smlight one, 2.x.x)? They released a lot of fixes recently. This won't fix the ultimate issue here though, just maybe a cleaner initial startup.

@voc0der How familiar are you with docker? Any chance you could edit a few files so we can figure out where exactly the darn thing is stopping?

I am not the original reporter but as a side note, I received yesterday from SMLIGHT current dev OTA update 2.4.2_dev applicable to both SLZB-06 and -06M. I still see:

[12:31:00] INFO: Preparing to start...
[12:31:01] INFO: Socat not enabled
[12:31:06] INFO: Starting Zigbee2MQTT...
[2024-06-28 12:31:16] info:     z2m: Logging to console, file (filename: log.log)
[2024-06-28 12:31:16] info:     z2m: Starting Zigbee2MQTT version 1.38.0 (commit #unknown)
[2024-06-28 12:31:16] info:     z2m: Starting zigbee-herdsman (0.49.2)
[2024-06-28 12:31:17] info:     zh:ember: Using default stack config.
[2024-06-28 12:31:17] info:     zh:ember: ======== Ember Adapter Starting ========
[2024-06-28 12:31:17] info:     zh:ember:ezsp: ======== EZSP starting ========
[2024-06-28 12:31:17] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-06-28 12:31:17] info:     zh:ember:uart:ash: Socket ready
[2024-06-28 12:31:17] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-06-28 12:31:17] error:    zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-06-28 12:31:17] error:    zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR
[2024-06-28 12:31:17] error:    zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-06-28 12:31:17] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-06-28 12:31:17] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-06-28 12:31:18] info:     zh:ember:uart:ash: ======== ASH connected ========
[2024-06-28 12:31:18] info:     zh:ember:uart:ash: ======== ASH started ========
[2024-06-28 12:31:18] info:     zh:ember:ezsp: ======== EZSP started ========
[2024-06-28 12:31:19] warning:  zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e]
[2024-06-28 12:31:19] error:    zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE.
[2024-06-28 12:31:19] error:    zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR
[2024-06-28 12:31:19] error:    zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR.
[2024-06-28 12:31:19] error:    zh:ember: !!! NCP FATAL ERROR reason=HOST_FATAL_ERROR. ATTEMPTING RESET... !!!
[2024-06-28 12:31:19] info:     zh:ember:queue: Request dispatching stopped; queue=0 priorityQueue=0
[2024-06-28 12:31:19] info:     zh:ember:uart:ash: ASH COUNTERS since last clear:
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   Total frames: RX=2, TX=3
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   Cancelled   : RX=1, TX=0
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   DATA frames : RX=0, TX=1
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   DATA bytes  : RX=0, TX=4
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   Retry frames: RX=0, TX=0
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   ACK frames  : RX=0, TX=1
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   NAK frames  : RX=0, TX=0
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   nRdy frames : RX=0, TX=0
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   CRC errors      : RX=0
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   Comm errors     : RX=0
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   Length < minimum: RX=0
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   Length > maximum: RX=0
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   Bad controls    : RX=0
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   Bad lengths     : RX=0
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   Bad ACK numbers : RX=0
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   Out of buffers  : RX=0
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   Retry dupes     : RX=0
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   Out of sequence : RX=0
[2024-06-28 12:31:19] info:     zh:ember:uart:ash:   ACK timeouts    : RX=0
[2024-06-28 12:31:19] info:     zh:ember:uart:ash: ======== ASH stopped ========
[2024-06-28 12:31:19] info:     zh:ember:ezsp: ======== EZSP stopped ========
[2024-06-28 12:31:19] info:     zh:ember: ======== Ember Adapter Stopped ========
[2024-06-28 12:31:20] info:     zh:ember: ======== Ember Adapter Starting ========
[2024-06-28 12:31:20] info:     zh:ember:ezsp: ======== EZSP starting ========
[2024-06-28 12:31:20] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-06-28 12:31:20] info:     zh:ember:uart:ash: Socket ready
[2024-06-28 12:31:20] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-06-28 12:31:21] info:     zh:ember:uart:ash: ======== ASH connected ========
[2024-06-28 12:31:21] info:     zh:ember:uart:ash: ======== ASH started ========
[2024-06-28 12:31:21] info:     zh:ember:ezsp: ======== EZSP started ========
[2024-06-28 12:31:21] info:     zh:ember: [STACK STATUS] Network up.
[2024-06-28 12:31:21] info:     zh:ember: [INIT TC] NCP network matches config.
[2024-06-28 12:31:21] info:     zh:ember: [CONCENTRATOR] Started source route discovery. 1247ms until next broadcast.
[2024-06-28 12:31:21] info:     zh:ember:queue: Request dispatching started.

From SMLIGHT SLZB-06M web admin GUI [-> Admin tools -> Logs] (http://192.168.xx.xxx/settings/system_log)

[08:38:01] setup | Starting firmware: v2.4.2.dev
[08:38:02] ConfigHelper | LittleFS mounted
[08:38:02] ConfigHelper | load config
[08:38:02] ConfigHelper | config open: Ok
[08:38:02] setup | Config loaded
[08:38:02] setup | Reboot reason: 3
[08:38:02] setup | Coordinator mode: LAN
[08:38:02] setup | Radio FW version: 20240510
[08:38:02] setup | Device type: SLZB-06M
[08:38:02] setup | Radio mode: ZB COORD
[08:38:02] Network | init
[08:38:02] L_Y,L_B | status: 1
[08:38:04] Network | EVENT_ETH_START
[08:38:04] Network | EVENT_ETH_CONNECTED
[08:38:04] Network | ETH init: OK
[08:38:04] setup | Filesystem size: 3456
[08:38:04] setup | Filesystem used: 248
[08:38:04] setup | done
[08:38:11] Network | [MDNS] Started
[08:38:11] Network | EVENT_ETH_GOT_IP
[08:38:11] Network | ETH MAC: D4:8A:FC:xx:xx:xx IPv4: 192.168.x.x GW: 192.168.x.x Speed: 100Mbps DNS1: 192.168.x.x DNS2: 0.0.0.0
[08:38:11] Network | fireNetworkUp
[08:38:11] taskZB | Start task
[08:38:11] taskZB | Starting server on port: 6638
[08:38:11] Web | Webserver started
[08:38:11] time | time sync start
[08:38:11] internet | connected
[10:38:11] time | timezone: CET-1CEST,M3.5.0,M10.5.0/3
[10:38:11] time | Friday, June 28 2024 10:38:11
[10:38:11] taskTimeSync | Heap: 1376
[10:38:11] time | stop task
[10:38:12] taskZB | New client: 192.168.x.x id: 0
[10:38:12] Network | [POST] result: 200
[10:38:12] Network | [POST] response: New record [on] created successfullyNew record [lo] created successfully
[10:38:12] stats | Statistics sent
[10:38:12] stats | Heap: 2384
[10:38:13] [ZBCHK] | Wrong answer
[10:38:13] [ZBVER] | Unknown
[10:38:14] [ZBCHK] | done
[12:30:54] taskZB | Client disconnected, id: 0
[12:31:17] taskZB | New client: 192.168.x.x id: 0
[12:31:19] taskZB | Client disconnected, id: 0
[12:31:20] taskZB | New client: 192.168.x.x id: 0

Note the ZBCHK and ZBVER commands failing.

[Edit: SMLight says these ZBCHK and ZBVER commands failing messages are harmless. However, I also need to start the Zigbee2MGTT manually, the watchdog ran by HA does not kick in somehow to realize it is down.]

@Nerivec I'm pretty comfortable around docker/git/build, so if you have anything in mind I am open to trying.

I still need to try the no HW firmware and post more logs but well, ideally it would work either way?

@mmokrejs According to darkxst, these ZBCHK and ZBVER can be ignored when not using official OTA images (ESP32 side trying to check Zigbee side).

@voc0der The no-hw firmware will only cleanup the startup sequence (very beginning, the RESET_WATCHDOG fail), but won't solve the issue further down. See if you can replace the dist folder for herdsman in your zigbee2mqtt (dev) installation folder (should be in node_modules/zigbee-herdsman/dist) with the following dist.zip (replace/overwrite all).

Here's the log: not exactly the same error, so I won't try to make any assumptions. It does fail to start as before.

Logs

``` Using '/app/data' as data directory Starting Zigbee2MQTT without watchdog. [2024-06-28 13:31:40] info: z2m: Logging to console, file (filename: log.log) [2024-06-28 13:31:40] debug: z2m: Loaded state from file /app/data/state.json [2024-06-28 13:31:40] info: z2m: Starting Zigbee2MQTT version 1.38.0-dev (commit #c48db3f) [2024-06-28 13:31:40] info: z2m: Starting zigbee-herdsman (0.50.0) [2024-06-28 13:31:40] debug: z2m: Using zigbee-herdsman with settings: '"{\"network\":{\"panID\":28602,\"extendedPanID\":[222,158,171,2,134,204,14,1],\"channelList\":[25],\"networkKey\":\"HIDDEN\"},\"databasePath\":\"/app/data/database.db\",\"databaseBackupPath\":\"/app/data/database.db.backup\",\"backupPath\":\"/app/data/coordinator_backup.json\",\"serialPort\":{\"rtscts\":true,\"path\":\"/dev/ttyACM0\",\"adapter\":\"ember\"},\"adapter\":{\"concurrent\":null,\"delay\":null,\"disableLED\":false}}"' [2024-06-28 13:31:40] info: zh:ember: Using default stack config. [2024-06-28 13:31:40] debug: zh:ember: Using delay=5. [2024-06-28 13:31:40] debug: zh:controller: Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":"HIDDEN","panID":28602,"extendedPanID":[222,158,171,2,134,204,14,1],"channelList":[25]},"serialPort":{"rtscts":true,"path":"/dev/ttyACM0","adapter":"ember"},"databasePath":"/app/data/database.db","databaseBackupPath":"/app/data/database.db.backup","backupPath":"/app/data/coordinator_backup.json","adapter":{"disableLED":false,"concurrent":null,"delay":null}}' [2024-06-28 13:31:40] info: zh:ember: ======== Ember Adapter Starting ======== [2024-06-28 13:31:40] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-06-28 13:31:40] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-06-28 13:31:40] debug: zh:ember:uart:ash: Opening serial port with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":true,"autoOpen":false,"parity":"none","stopBits":1,"xon":false,"xoff":false} [2024-06-28 13:31:40] info: zh:ember:uart:ash: Serial port opened [2024-06-28 13:31:40] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-06-28 13:31:40] debug: zh:ember:uart:ash: ---> [FRAME type=RST] [2024-06-28 13:31:40] debug: zh:ember:uart:ash: Waiting for RSTACK... 0/2500 [2024-06-28 13:31:40] debug: zh:ember:uart:ash: <--- [FRAME type=ERROR] [2024-06-28 13:31:40] error: zh:ember:uart:ash: Received ERROR from adapter while connecting, with code=RESET_WATCHDOG. [2024-06-28 13:31:40] error: zh:ember:uart:ash: ASH disconnected | Adapter status: ASH_NCP_FATAL_ERROR [2024-06-28 13:31:40] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR. [2024-06-28 13:31:40] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-06-28 13:31:40] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-06-28 13:31:40] debug: zh:ember:uart:ash: ---> [FRAME type=RST] [2024-06-28 13:31:40] debug: zh:ember:uart:ash: Waiting for RSTACK... 0/2500 [2024-06-28 13:31:40] debug: zh:ember:uart:ash: Waiting for RSTACK... 100/2500 [2024-06-28 13:31:41] debug: zh:ember:uart:ash: Waiting for RSTACK... 200/2500 [2024-06-28 13:31:41] debug: zh:ember:uart:ash: Waiting for RSTACK... 300/2500 [2024-06-28 13:31:41] debug: zh:ember:uart:ash: Waiting for RSTACK... 400/2500 [2024-06-28 13:31:41] debug: zh:ember:uart:ash: Waiting for RSTACK... 500/2500 [2024-06-28 13:31:41] debug: zh:ember:uart:ash: Waiting for RSTACK... 600/2500 [2024-06-28 13:31:41] debug: zh:ember:uart:ash: Waiting for RSTACK... 700/2500 [2024-06-28 13:31:41] debug: zh:ember:uart:ash: Waiting for RSTACK... 800/2500 [2024-06-28 13:31:41] debug: zh:ember:uart:ash: Waiting for RSTACK... 900/2500 [2024-06-28 13:31:41] debug: zh:ember:uart:ash: <--- [FRAME type=RSTACK] [2024-06-28 13:31:41] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-06-28 13:31:41] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-06-28 13:31:41] info: zh:ember:uart:ash: ======== ASH started ======== [2024-06-28 13:31:41] info: zh:ember:ezsp: ======== EZSP started ======== [2024-06-28 13:31:41] debug: zh:ember:ezsp: ===> [FRAME: ID=0:"VERSION" Seq=0 Len=4] [2024-06-28 13:31:41] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-06-28 13:31:42] warning: zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e] [2024-06-28 13:31:42] debug: zh:ember:uart:ash: <--- [FRAME type=RSTACK] [2024-06-28 13:31:42] error: zh:ember:uart:ash: Received unexpected reset from adapter, with reason=RESET_SOFTWARE. [2024-06-28 13:31:42] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | Adapter status: ASH_NCP_FATAL_ERROR [2024-06-28 13:31:42] error: zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR. [2024-06-28 13:31:42] error: zh:ember: !!! ADAPTER FATAL ERROR reason=HOST_FATAL_ERROR. !!! [2024-06-28 13:31:42] info: zh:ember: Attempting adapter reset... [2024-06-28 13:31:42] info: zh:ember:queue: Request dispatching stopped; queue=0 priorityQueue=0 [2024-06-28 13:31:42] info: zh:ember:uart:ash: ASH COUNTERS since last clear: [2024-06-28 13:31:42] info: zh:ember:uart:ash: Total frames: RX=2, TX=3 [2024-06-28 13:31:42] info: zh:ember:uart:ash: Cancelled : RX=1, TX=0 [2024-06-28 13:31:42] info: zh:ember:uart:ash: DATA frames : RX=0, TX=1 [2024-06-28 13:31:42] info: zh:ember:uart:ash: DATA bytes : RX=0, TX=4 [2024-06-28 13:31:42] info: zh:ember:uart:ash: Retry frames: RX=0, TX=0 [2024-06-28 13:31:42] info: zh:ember:uart:ash: ACK frames : RX=0, TX=1 [2024-06-28 13:31:42] info: zh:ember:uart:ash: NAK frames : RX=0, TX=0 [2024-06-28 13:31:42] info: zh:ember:uart:ash: nRdy frames : RX=0, TX=0 [2024-06-28 13:31:42] info: zh:ember:uart:ash: CRC errors : RX=0 [2024-06-28 13:31:42] info: zh:ember:uart:ash: Comm errors : RX=0 [2024-06-28 13:31:42] info: zh:ember:uart:ash: Length < minimum: RX=0 [2024-06-28 13:31:42] info: zh:ember:uart:ash: Length > maximum: RX=0 [2024-06-28 13:31:42] info: zh:ember:uart:ash: Bad controls : RX=0 [2024-06-28 13:31:42] info: zh:ember:uart:ash: Bad lengths : RX=0 [2024-06-28 13:31:42] info: zh:ember:uart:ash: Bad ACK numbers : RX=0 [2024-06-28 13:31:42] info: zh:ember:uart:ash: Out of buffers : RX=0 [2024-06-28 13:31:42] info: zh:ember:uart:ash: Retry dupes : RX=0 [2024-06-28 13:31:42] info: zh:ember:uart:ash: Out of sequence : RX=0 [2024-06-28 13:31:42] info: zh:ember:uart:ash: ACK timeouts : RX=0 [2024-06-28 13:31:42] error: zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR. [2024-06-28 13:31:42] info: zh:ember:uart:ash: Port closed. [2024-06-28 13:31:42] info: zh:ember:uart:ash: ======== ASH stopped ======== [2024-06-28 13:31:42] info: zh:ember:ezsp: ======== EZSP stopped ======== [2024-06-28 13:31:42] info: zh:ember: ======== Ember Adapter Stopped ======== [2024-06-28 13:31:43] info: zh:ember: ======== Ember Adapter Starting ======== [2024-06-28 13:31:43] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-06-28 13:31:43] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-06-28 13:31:43] debug: zh:ember:uart:ash: Opening serial port with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":true,"autoOpen":false,"parity":"none","stopBits":1,"xon":false,"xoff":false} [2024-06-28 13:31:43] info: zh:ember:uart:ash: Serial port opened [2024-06-28 13:31:43] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-06-28 13:31:43] debug: zh:ember:uart:ash: ---> [FRAME type=RST] [2024-06-28 13:31:43] debug: zh:ember:uart:ash: Waiting for RSTACK... 0/2500 [2024-06-28 13:31:43] debug: zh:ember:uart:ash: Waiting for RSTACK... 100/2500 [2024-06-28 13:31:43] debug: zh:ember:uart:ash: Waiting for RSTACK... 200/2500 [2024-06-28 13:31:43] debug: zh:ember:uart:ash: Waiting for RSTACK... 300/2500 [2024-06-28 13:31:43] debug: zh:ember:uart:ash: Waiting for RSTACK... 400/2500 [2024-06-28 13:31:43] debug: zh:ember:uart:ash: Waiting for RSTACK... 500/2500 [2024-06-28 13:31:44] debug: zh:ember:uart:ash: Waiting for RSTACK... 600/2500 [2024-06-28 13:31:44] debug: zh:ember:uart:ash: Waiting for RSTACK... 700/2500 [2024-06-28 13:31:44] debug: zh:ember:uart:ash: Waiting for RSTACK... 800/2500 [2024-06-28 13:31:44] debug: zh:ember:uart:ash: Waiting for RSTACK... 900/2500 [2024-06-28 13:31:44] debug: zh:ember:uart:ash: Waiting for RSTACK... 1000/2500 [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=RSTACK] [2024-06-28 13:31:44] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-06-28 13:31:44] info: zh:ember:uart:ash: ======== ASH started ======== [2024-06-28 13:31:44] info: zh:ember:ezsp: ======== EZSP started ======== [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=0:"VERSION" Seq=0 Len=4] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=0:"VERSION" Seq=0 Len=7] [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=0:"VERSION" Seq=1 Len=6] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=0:"VERSION" Seq=1 Len=9] [2024-06-28 13:31:44] info: zh:ember: Adapter EZSP protocol version (13) lower than Host. Switched. [2024-06-28 13:31:44] debug: zh:ember: Adapter info: EZSPVersion=13 StackType=2 StackVersion=29744 [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=170:"GET_VALUE" Seq=2 Len=6] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=170:"GET_VALUE" Seq=2 Len=14] [2024-06-28 13:31:44] info: zh:ember: Adapter version info: {"ezsp":13,"revision":"7.4.3 [GA]","build":0,"major":7,"minor":4,"patch":3,"special":0,"type":170} [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=3 Len=8] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=3 Len=6] [2024-06-28 13:31:44] debug: zh:ember: [EzspConfigId] SET "INDIRECT_TRANSMISSION_TIMEOUT" TO "7680" with status=OK. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=4 Len=8] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=4 Len=6] [2024-06-28 13:31:44] debug: zh:ember: [EzspConfigId] SET "MAX_HOPS" TO "30" with status=OK. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=5 Len=8] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=5 Len=6] [2024-06-28 13:31:44] debug: zh:ember: [EzspConfigId] SET "SUPPORTED_NETWORKS" TO "1" with status=OK. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=6 Len=7] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=6 Len=6] [2024-06-28 13:31:44] debug: zh:ember: [EzspPolicyId] SET "BINDING_MODIFICATION_POLICY" TO "18" with status=OK. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=7 Len=7] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=7 Len=6] [2024-06-28 13:31:44] debug: zh:ember: [EzspPolicyId] SET "MESSAGE_CONTENTS_IN_CALLBACK_POLICY" TO "64" with status=OK. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=171:"SET_VALUE" Seq=8 Len=9] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=171:"SET_VALUE" Seq=8 Len=6] [2024-06-28 13:31:44] debug: zh:ember: [EzspValueId] SET "TRANSIENT_DEVICE_TIMEOUT" TO "16,39" with status=OK. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=21:"SET_MANUFACTURER_CODE" Seq=9 Len=7] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=21:"SET_MANUFACTURER_CODE" Seq=9 Len=5] [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=10 Len=8] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=10 Len=6] [2024-06-28 13:31:44] debug: zh:ember: [EzspConfigId] SET "STACK_PROFILE" TO "2" with status=OK. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=11 Len=8] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=11 Len=6] [2024-06-28 13:31:44] debug: zh:ember: [EzspConfigId] SET "SECURITY_LEVEL" TO "5" with status=OK. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=12 Len=8] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=12 Len=6] [2024-06-28 13:31:44] debug: zh:ember: [EzspConfigId] SET "MAX_END_DEVICE_CHILDREN" TO "32" with status=OK. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=13 Len=8] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=13 Len=6] [2024-06-28 13:31:44] debug: zh:ember: [EzspConfigId] SET "END_DEVICE_POLL_TIMEOUT" TO "8" with status=OK. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=14 Len=8] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=14 Len=6] [2024-06-28 13:31:44] debug: zh:ember: [EzspConfigId] SET "TRANSIENT_KEY_TIMEOUT_S" TO "300" with status=OK. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=15 Len=10] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=15 Len=9] [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=2:"ADD_ENDPOINT" Seq=16 Len=63] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=2:"ADD_ENDPOINT" Seq=16 Len=6] [2024-06-28 13:31:44] debug: zh:ember: Registered endpoint '1'. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=17 Len=10] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=17 Len=6] [2024-06-28 13:31:44] debug: zh:ember: Registered multicast table entry (0): {"multicastId":0,"endpoint":1,"networkIndex":0}. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=18 Len=10] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=18 Len=6] [2024-06-28 13:31:44] debug: zh:ember: Registered multicast table entry (1): {"multicastId":901,"endpoint":1,"networkIndex":0}. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=19 Len=10] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=19 Len=9] [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=2:"ADD_ENDPOINT" Seq=20 Len=17] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=2:"ADD_ENDPOINT" Seq=20 Len=6] [2024-06-28 13:31:44] debug: zh:ember: Registered endpoint '242'. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=21 Len=10] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=21 Len=6] [2024-06-28 13:31:44] debug: zh:ember: Registered multicast table entry (2): {"multicastId":2948,"endpoint":242,"networkIndex":0}. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=22 Len=7] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=22 Len=6] [2024-06-28 13:31:44] debug: zh:ember: [EzspPolicyId] SET "TC_KEY_REQUEST_POLICY" TO "81" with status=OK. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=23 Len=7] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=23 Len=6] [2024-06-28 13:31:44] debug: zh:ember: [EzspPolicyId] SET "APP_KEY_REQUEST_POLICY" TO "96" with status=OK. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=24 Len=7] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=24 Len=6] [2024-06-28 13:31:44] debug: zh:ember: [EzspPolicyId] SET "TRUST_CENTER_POLICY" TO "3" with status=OK. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=23:"NETWORK_INIT" Seq=25 Len=7] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=2] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=23:"NETWORK_INIT" Seq=25 Len=6] [2024-06-28 13:31:44] debug: zh:ember: [INIT TC] Network init status=OK. [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [CBFRAME: ID=25:"STACK_STATUS_HANDLER" Seq=25 Len=6] [2024-06-28 13:31:44] debug: zh:ember:ezsp: ezspStackStatusHandler(): callback called with: [status=NETWORK_UP] [2024-06-28 13:31:44] info: zh:ember: [STACK STATUS] Network up. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=40:"GET_NETWORK_PARAMETERS" Seq=26 Len=5] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=3] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=3] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=40:"GET_NETWORK_PARAMETERS" Seq=26 Len=27] [2024-06-28 13:31:44] debug: zh:ember: [INIT TC] Current network config={"networkKeyDistribute":false,"networkKey":[221,75,142,123,205,153,202,191,222,203,211,151,148,58,233,216],"panID":28602,"extendedPanID":[222,158,171,2,134,204,14,1],"channelList":[25]} [2024-06-28 13:31:44] debug: zh:ember: [INIT TC] Current adapter network: nodeType=COORDINATOR params={"extendedPanId":[222,158,171,2,134,204,14,1],"panId":28602,"radioTxPower":5,"radioChannel":25,"joinMethod":0,"nwkManagerId":0,"nwkUpdateId":0,"channels":134215680} [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=276:"EXPORT_KEY" Seq=27 Len=23] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=4] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=4] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=276:"EXPORT_KEY" Seq=27 Len=25] [2024-06-28 13:31:44] debug: zh:ember: [INIT TC] Current adapter network: networkKey={{REDACTED}} [2024-06-28 13:31:44] info: zh:ember: [INIT TC] Adapter network matches config. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=16:"SET_CONCENTRATOR" Seq=28 Len=15] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=5] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=5] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=16:"SET_CONCENTRATOR" Seq=28 Len=6] [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=90:"SET_SOURCE_ROUTE_DISCOVERY_MODE" Seq=29 Len=6] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=6] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=6] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=90:"SET_SOURCE_ROUTE_DISCOVERY_MODE" Seq=29 Len=9] [2024-06-28 13:31:44] info: zh:ember: [CONCENTRATOR] Started source route discovery. 1248ms until next broadcast. [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=40:"GET_NETWORK_PARAMETERS" Seq=30 Len=5] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=7] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=7] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=40:"GET_NETWORK_PARAMETERS" Seq=30 Len=27] [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=24:"NETWORK_STATE" Seq=31 Len=5] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=0] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=0] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=24:"NETWORK_STATE" Seq=31 Len=6] [2024-06-28 13:31:44] debug: zh:ember:ezsp: ===> [FRAME: ID=38:"GET_EUI64" Seq=32 Len=5] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=1] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-06-28 13:31:44] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=1] Added to rxQueue [2024-06-28 13:31:44] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-06-28 13:31:44] debug: zh:ember:ezsp: <=== [FRAME: ID=38:"GET_EUI64" Seq=32 Len=13] [2024-06-28 13:31:44] debug: zh:ember: [INIT] Network Ready! {"eui64":"0xbc026efffe23387d","parameters":{"extendedPanId":[222,158,171,2,134,204,14,1],"panId":28602,"radioTxPower":5,"radioChannel":25,"joinMethod":0,"nwkManagerId":0,"nwkUpdateId":0,"channels":134215680},"status":2} [2024-06-28 13:31:44] info: zh:ember:queue: Request dispatching started. [2024-06-28 13:31:44] debug: zh:ember: initEzsp() done. [2024-06-28 13:31:44] debug: zh:ember: start() done. [2024-06-28 13:31:56] debug: zh:ember:ezsp: =x=> [FRAME: ID=38:"GET_EUI64" Seq=32 Len=13] Error: ASH_ERROR_TIMEOUTS [2024-06-28 13:31:56] error: zh:ember:ezsp: ERROR Transaction failure; status=undefined. Last Frame: [FRAME: ID=38:"GET_EUI64" Seq=32 Len=13]. [2024-06-28 13:31:56] error: zh:ember: !!! ADAPTER FATAL ERROR reason=undefined. !!! [2024-06-28 13:31:56] info: zh:ember: Attempting adapter reset... [2024-06-28 13:31:56] info: zh:ember:queue: Request dispatching stopped; queue=0 priorityQueue=0 [2024-06-28 13:31:56] info: zh:ember:uart:ash: ASH COUNTERS since last clear: [2024-06-28 13:31:56] info: zh:ember:uart:ash: Total frames: RX=35, TX=68 [2024-06-28 13:31:56] info: zh:ember:uart:ash: Cancelled : RX=0, TX=0 [2024-06-28 13:31:56] info: zh:ember:uart:ash: DATA frames : RX=34, TX=33 [2024-06-28 13:31:56] info: zh:ember:uart:ash: DATA bytes : RX=292, TX=332 [2024-06-28 13:31:56] info: zh:ember:uart:ash: Retry frames: RX=0, TX=0 [2024-06-28 13:31:56] info: zh:ember:uart:ash: ACK frames : RX=0, TX=34 [2024-06-28 13:31:56] info: zh:ember:uart:ash: NAK frames : RX=0, TX=0 [2024-06-28 13:31:56] info: zh:ember:uart:ash: nRdy frames : RX=0, TX=0 [2024-06-28 13:31:56] info: zh:ember:uart:ash: CRC errors : RX=0 [2024-06-28 13:31:56] info: zh:ember:uart:ash: Comm errors : RX=0 [2024-06-28 13:31:56] info: zh:ember:uart:ash: Length < minimum: RX=0 [2024-06-28 13:31:56] info: zh:ember:uart:ash: Length > maximum: RX=0 [2024-06-28 13:31:56] info: zh:ember:uart:ash: Bad controls : RX=0 [2024-06-28 13:31:56] info: zh:ember:uart:ash: Bad lengths : RX=0 [2024-06-28 13:31:56] info: zh:ember:uart:ash: Bad ACK numbers : RX=0 [2024-06-28 13:31:56] info: zh:ember:uart:ash: Out of buffers : RX=0 [2024-06-28 13:31:56] info: zh:ember:uart:ash: Retry dupes : RX=0 [2024-06-28 13:31:56] info: zh:ember:uart:ash: Out of sequence : RX=0 [2024-06-28 13:31:56] info: zh:ember:uart:ash: ACK timeouts : RX=0 [2024-06-28 13:31:56] error: z2m: Error while starting zigbee-herdsman [2024-06-28 13:31:56] error: z2m: Failed to start zigbee [2024-06-28 13:31:56] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions [2024-06-28 13:31:56] error: z2m: Exiting... [2024-06-28 13:31:56] error: z2m: Error: at Ezsp.ezspVersion (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:1352:19) at EmberAdapter.emberVersion (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1528:63) at EmberAdapter.initEzsp (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:770:9) at EmberAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1889:24) at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:129:29) at Zigbee.start (/app/lib/zigbee.ts:63:27) at Controller.start (/app/lib/controller.ts:139:27) at start (/app/index.js:154:5) ```

@voc0der Any chance you can find me on Discord (can DM me from zigbee2mqtt server)? It'll be easier to share stuff without polluting this thread too much (weird appears to only be getting weirder... 😅).

@robotsmarthomes and @MilesTEG1 can you confirm your adapter type/model, and setup for z2m and if it's exactly the same, or just similar?

@robotsmarthomes and @MilesTEG1 can you confirm your adapter type/model, and setup for z2m and if it's exactly the same, or just similar?

Hello 👋🏻 I posted this issue some minutes ago 😊 I have a SMLIGHT SLZB-06M, my Z2M is an addon inside HAOS witch runs as a proxmox VM. The adapter seems to be identical, for the setup I'm not sure what he has.

If you need more info , tell me, if I can provide them I will (I'm not a developer 😊).

As user of the SLZB-06M I can also confirm that I need to start at least twice the z2m container in order to properly use it. Especially due to updates of the containers, it regularly occurs.

See my log attached. Bad start, Z2M fails to start: log (4).log

And the second "clean" start:

log (5).log

Hello,

Apologies I missed the notification earlier

I am currently running 2x SLZB-06M’s on two different zigbee2mqtt networks using the same raspberry pi4.

Latest core firmware 2305 Latest Zigbee firmware - ember

Each network in the home has about 30x Zigbee Relays and also has 6x mmWave human presence sensors (very chatty in the logs)

I am unable to start the zigbee2mqtt without deleting the backup_config.json file.

It starts though but I’m finding this ember very slow and unresponsive at times.

On Sat, 29 Jun 2024 at 6:49 AM, fir3drag0n @.***> wrote:

As user of the SLZB-06M I can also confirm that I need to start at least twice the z2m container in order to properly use it. Especially due to updates of the containers, it regularly occurs.

— Reply to this email directly, view it on GitHub https://github.com/Koenkk/zigbee2mqtt/issues/23120#issuecomment-2197639805, or unsubscribe https://github.com/notifications/unsubscribe-auth/A2V2X6QNIFFTGROXZYLV42DZJXD7DAVCNFSM6AAAAABJVNW2DKVHI2DSMVQWIX3LMV43OSLTON2WKQ3PNVWWK3TUHMZDCOJXGYZTSOBQGU . You are receiving this because you were mentioned.Message ID: @.***>

Following because of #22249, which also includes failures at starting with "ember" for me.

Following, also using SLZB-06M seeing the same thing. Have to restart z2m multiple times to get it up and running.

Hello here, I fixed my problem with error ROUTE_ERROR_ADDRESS_CONFLICT. But I still have an issue with startup of Z2M: it crashes and I need to reboot one time at least to get it functionnal. Here the log for the first book, the failed one:

[2024-07-03 23:29:16] info:     z2m: Logging to console, file (filename: log.log)
[2024-07-03 23:29:16] info:     z2m: Starting Zigbee2MQTT version 1.39.0 (commit #unknown)
[2024-07-03 23:29:16] info:     z2m: Starting zigbee-herdsman (0.50.1)
[2024-07-03 23:29:16] info:     zh:ember: Using default stack config.
[2024-07-03 23:29:16] info:     zh:ember: ======== Ember Adapter Starting ========
[2024-07-03 23:29:16] info:     zh:ember:ezsp: ======== EZSP starting ========
[2024-07-03 23:29:16] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-07-03 23:29:16] info:     zh:ember:uart:ash: Socket ready
[2024-07-03 23:29:16] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-07-03 23:29:16] error:    zh:ember:uart:ash: Received frame with CRC error
[2024-07-03 23:29:16] error:    zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-07-03 23:29:16] error:    zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR
[2024-07-03 23:29:16] error:    zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-07-03 23:29:17] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-07-03 23:29:17] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-07-03 23:29:17] info:     zh:ember:uart:ash: ======== ASH connected ========
[2024-07-03 23:29:18] info:     zh:ember:uart:ash: ======== ASH started ========
[2024-07-03 23:29:18] info:     zh:ember:ezsp: ======== EZSP started ========
[2024-07-03 23:29:19] warning:  zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e]
[2024-07-03 23:29:19] error:    zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE.
[2024-07-03 23:29:19] error:    zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR
[2024-07-03 23:29:19] error:    zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR.
[2024-07-03 23:29:19] error:    zh:ember: !!! NCP FATAL ERROR reason=HOST_FATAL_ERROR. ATTEMPTING RESET... !!!
[2024-07-03 23:29:19] info:     zh:ember:queue: Request dispatching stopped; queue=0 priorityQueue=0
[2024-07-03 23:29:19] info:     zh:ember:uart:ash: ASH COUNTERS since last clear:
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   Total frames: RX=2, TX=3
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   Cancelled   : RX=1, TX=0
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   DATA frames : RX=0, TX=1
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   DATA bytes  : RX=0, TX=4
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   Retry frames: RX=0, TX=0
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   ACK frames  : RX=0, TX=1
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   NAK frames  : RX=0, TX=0
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   nRdy frames : RX=0, TX=0
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   CRC errors      : RX=0
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   Comm errors     : RX=0
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   Length < minimum: RX=0
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   Length > maximum: RX=0
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   Bad controls    : RX=0
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   Bad lengths     : RX=0
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   Bad ACK numbers : RX=0
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   Out of buffers  : RX=0
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   Retry dupes     : RX=0
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   Out of sequence : RX=0
[2024-07-03 23:29:19] info:     zh:ember:uart:ash:   ACK timeouts    : RX=0
[2024-07-03 23:29:19] info:     zh:ember:uart:ash: ======== ASH stopped ========
[2024-07-03 23:29:19] info:     zh:ember:ezsp: ======== EZSP stopped ========
[2024-07-03 23:29:19] info:     zh:ember: ======== Ember Adapter Stopped ========
[2024-07-03 23:29:19] info:     zh:ember: ======== Ember Adapter Starting ========
[2024-07-03 23:29:19] info:     zh:ember:ezsp: ======== EZSP starting ========
[2024-07-03 23:29:19] info:     zh:ember:uart:ash: ======== ASH NCP reset ========
[2024-07-03 23:29:19] info:     zh:ember:uart:ash: Socket ready
[2024-07-03 23:29:19] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-07-03 23:29:20] info:     zh:ember:uart:ash: ======== ASH connected ========
[2024-07-03 23:29:20] info:     zh:ember:uart:ash: ======== ASH started ========
[2024-07-03 23:29:20] info:     zh:ember:ezsp: ======== EZSP started ========
[2024-07-03 23:29:21] info:     zh:ember: [STACK STATUS] Network up.
[2024-07-03 23:29:21] info:     zh:ember: [INIT TC] NCP network matches config.
[2024-07-03 23:29:21] info:     zh:ember: [CONCENTRATOR] Started source route discovery. 1248ms until next broadcast.
[2024-07-03 23:29:21] info:     zh:ember:queue: Request dispatching started.

Had almost identical issue above

[2024-07-09 22:25:55] error: zh:ember:uart:ash: Received ERROR from NCP while connecting, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT. [2024-07-09 22:25:55] error: zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR [2024-07-09 22:25:55] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR. [2024-07-09 22:25:55] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR. [2024-07-09 22:25:55] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR. [2024-07-09 22:25:55] info: zh:ember:uart:ash: ======== ASH NCP reset ======== [2024-07-09 22:25:55] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-07-09 22:25:56] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-07-09 22:25:56] info: zh:ember:uart:ash: ======== ASH started ======== [2024-07-09 22:25:56] info: zh:ember:ezsp: ======== EZSP started ======== [2024-07-09 22:25:57] warning: zh:ember:uart:ash: Frame(s) in progress cancelled in [1ac1020b0a527e] [2024-07-09 22:25:57] error: zh:ember:uart:ash: Received unexpected reset from NCP, with reason=RESET_SOFTWARE. [2024-07-09 22:25:57] error: zh:ember:uart:ash: ASH disconnected: ASH_ERROR_NCP_RESET | NCP status: ASH_NCP_FATAL_ERROR [2024-07-09 22:25:57] error: zh:ember:uart:ash: Error while parsing received frame, status=HOST_FATAL_ERROR. [2024-07-09 22:25:57] error: zh:ember: !!! NCP FATAL ERROR reason=HOST_FATAL_ERROR. ATTEMPTING RESET... !!!

Switched to "adapter: ezsp" from ember and looks like it works with latest firmware (got warnings regarding migration to ember driver) [2024-07-09 22:38:28] warning: zh:ezsp: Deprecated driver 'ezsp' currently in use, 'ember' will become the officially supported EmberZNet driver in next release. but works so far

@andriikut These errors should be bypassed and allow Z2M to start regardless. That is unless you are affected by the issue where Z2M freezes after zh:ember:queue: Request dispatching started. Was this on slzb-06m too? If yes, what core firmware version, and do you have the logs from the SMLight interface (ESP side)? I'll pass them on.

Can anyone still affected by the freeze issue try with latest dev/edge and report back?

I can confirm the problem with latest dev

See log attached. log (6).log

@fir3drag0n Similar behavior but not the same problem it seems, or at least not at the same step. Do you have the logs from the SMLight interface for the ESP side? Seems your adapter is never receiving or replying to the very first command sent, on first run.

is there any update on this matter?

I running 2 SLZB-06M sticks, 1 works perfectly and the 2nd one reports the above errors with not starting the Z2M network; the setup of the 3rd stick is currently on hold as I need the 2nd one to work first.

@Kuechenfenster Can you make a list of the possible differences between the setup that is working, and the one that isn't; hardware and software? And provide log samples from both?

Jumping on as I have been having issues and looking for a solution. SLZB-06M with Ember struggles to start, Mosquitto is running but Z2MQTT says 502 bad gateway. Going directly to SLZB-06M IP I can see on the configuration page its connected to Z2MQTT. But no luck going to the HA UI page.

Changing the configuration back to ezsp seems to be smoothless.

Unsure what it is, but two log files Ember - log.log working ezsp log.log

Jumping on as I have been having issues and looking for a solution. SLZB-06M with Ember struggles to start, Mosquitto is running but Z2MQTT says 502 bad gateway. Going directly to SLZB-06M IP I can see on the configuration page its connected to Z2MQTT. But no luck going to the HA UI page.

Changing the configuration back to ezsp seems to be smoothless.

Unsure what it is, but two log files Ember - log.log working ezsp log.log

I have still the same problem. Temporary solution in few steps:

Stop z2m addon.
Change configuration to ember. Don't restart addon.
Restart SLZB-06M
Take some time (couple second to start adapter) - check if it started and it is ready.
Start z2m addon.

It will work till next restart of HA 🙂

@tandarra Problem looks to be related to spamming on start (common thread I see in the logs here), in your case, between 23:53:10 and 00:01:00, I see nearly 6000 incoming messages... from devices: 57425 (0xe051), 47113 (0xb809), 41954 (0xa3e2) about a third each (most seem to be from the Tuya manufacturer-specific cluster). All that before Z2M is done starting. Your ezsp logs don't have the startup sequence to compare though. Any chance you have the rest?

My Setup… HA: 2024.8.2 (Docker Container) z2m: 1.39.1 (Docker Container) mosquitto: 2.0.18 (Docker Container) SLZB-06M… Core: v2.5.0 ZigBee: 20240510 Adapter: ember

I have the same problem as described here. If I restart the z2m container in running, it does not come up successfully. Only when I restart the 06M stick does z2m start up successfully.

if I can test something please let me know, I have access to all files and configs.

I'm having similar problems #23761, but with Sonoff ZBDongle-E, and my z2m is working fine, but recently it is stopping working itself.. :c

Koenkk / zigbee2mqtt