zigbee2mqtt
zigbee2mqtt copied to clipboard
Published
2 weeks ago
•
Koenkk
Koenkk
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
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...
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
SkyConnectBlue, 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.
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_joinset totruein configuration.yaml. [2024-06-28 09:35:34] warning: z2m: Allowing new devices to join. [2024-06-28 09:35:34] warning: z2m: Setpermit_jointofalseonce 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.
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:
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.
