Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
Herreropl opened this issue Jun 21, 2024 · 75 comments
Open

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

Herreropl opened this issue Jun 21, 2024 · 75 comments
Labels
ember Issues related to ember driver problem Something isn't working

Comments

@Herreropl
Copy link

Herreropl commented Jun 21, 2024

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 #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)'

@Herreropl Herreropl added the problem Something isn't working label Jun 21, 2024
@Nerivec
Copy link
Collaborator

Nerivec commented Jun 22, 2024

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

@Nerivec Nerivec added the ember Issues related to ember driver label Jun 22, 2024
@Herreropl
Copy link
Author

Herreropl commented Jun 22, 2024

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

@robotsmarthomes
Copy link

Following- similar issue

@Nerivec
Copy link
Collaborator

Nerivec commented Jun 22, 2024

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?

@Herreropl
Copy link
Author

here you are :)

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

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

log.log

@Herreropl
Copy link
Author

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...

@Nerivec
Copy link
Collaborator

Nerivec commented Jun 23, 2024

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

@Herreropl
Copy link
Author

Herreropl commented Jun 23, 2024

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:

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

@mmokrejs
Copy link

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.

@Nerivec
Copy link
Collaborator

Nerivec commented Jun 25, 2024

@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

@Nerivec
Copy link
Collaborator

Nerivec commented Jun 26, 2024

@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?

@voc0der
Copy link

voc0der commented Jun 26, 2024

Here's what happens to me:

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

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

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

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

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


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

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

@Nerivec
Copy link
Collaborator

Nerivec commented Jun 26, 2024

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!?

@voc0der
Copy link

voc0der commented Jun 26, 2024

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]

@Herreropl
Copy link
Author

Herreropl commented Jun 26, 2024

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.

@Nerivec
Copy link
Collaborator

Nerivec commented Jun 26, 2024

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

@voc0der
Copy link

voc0der commented Jun 26, 2024

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.

@Herreropl
Copy link
Author

Herreropl commented Jun 28, 2024

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

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

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

@MilesTEG1
Copy link

Following- similar issue

@Nerivec
Copy link
Collaborator

Nerivec commented Jun 28, 2024

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?

@mmokrejs
Copy link

mmokrejs commented Jun 28, 2024

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.]

@voc0der
Copy link

voc0der commented Jun 28, 2024

@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?

@Nerivec
Copy link
Collaborator

Nerivec commented Jun 28, 2024

@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).

@voc0der
Copy link

voc0der commented Jun 28, 2024

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)

@Nerivec
Copy link
Collaborator

Nerivec commented Jun 28, 2024

@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... 😅).

@Nerivec
Copy link
Collaborator

Nerivec commented Jun 28, 2024

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

@MilesTEG1
Copy link

MilesTEG1 commented Jun 28, 2024

@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 😊).

@fir3drag0n
Copy link

fir3drag0n commented Jun 28, 2024

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

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

And the second "clean" start:

log (5).log

@DorjeDorf
Copy link

DorjeDorf commented Sep 18, 2024

@DorjeDorf so you switched back from ember to ezsp and upgraded core down to v2.3.6 and coordinator down to 20240330? Did you have to re-pair the ZigBee devices or did it work on the fly?

@TDCroPower Correct. No repairing needed. It all works. I do get the odd fault every couple weeks or so (then I need to power cycle either the device itself or the coordinator), but otherwise it works. Not the OTA, mind you. That is always broken and I get loads of uart errors in the logs when I try to OTA anything.

@sushain97
Copy link

I experienced similar issues with the SLZB-06M and seem to have things working with a slightly newer version combo than @DorjeDorf (and using ezsp as well). I suspect keeping the coordinator downgraded is the important part:

  • Core v2.5.6
  • Coordinator 20240330
  • Z2M 1.40.2

@DorjeDorf
Copy link

An update from me - since the issues never went away - especially with OTAs and regular reboots needed - I trashed the SLZB-06M and went back to Slaesh's trusty USB adapter.

All problems went away. I could finally OTA my devices and in general, the overall feeling is of a much better system. I don't know where the problem is - whether it's the SLZB or the driver or something else - in my case - I am happy now, finally after what I consider an unsuccessful experiment.

@bronzeblood
Copy link

Yeah im over my SLZB-06M what a unstable piece of shit.

@mmokrejs
Copy link

mmokrejs commented Oct 28, 2024

For me the latest firmware update 2.5.6 works:

Current core firmware version: v2.5.6

Release notes:

CHANGELOG
Fixed web server lockdown that occurred in some cases in v2.5.5
Added WG ping feature
Added 'DEV FIRMWARE' label for dev ZB firmware
Updated DE locale
Updated IT locale
Updated config helper locale
Changing header text 'ZHA/Z2M' when changing the mode to Thread
The device hostname is now displayed on every page
Fixed BT Proxy helper text
Fixed colons in CORE OTA dialog
Fixed radio mode change (This bug was in 2.5.4.dev)
Fixed accordions on OTA page

together with ZigBee update 20240510:

Your current firmware revision: 20240510
Firmware type: Zigbee Coordinator

Dev firmware
Revision: 20240510
Release notes

Updated version 10 May 2024
For 'adapter: ember' adapter settings in Z2M!
REQUIRES CORE v2.2.0 or higher
Please read https://github.com/Koenkk/zigbee2mqtt/discussions/21462
before flashing!
Green LED and Zigbee network scanning is not supported in this firmware!
Change your config:
adapter: ember
rtscts: false

@MilesTEG1
Copy link

Hello,
I own a SLZB-06M, and I had some troubles with it since I replaced my SkyConnect with it, keeping my Zigbee Network as is, and using the official zigbee firwmare and the Core firmware from SLZB.

But since I recreate my Zigbee Network from scratch, changing channel, and all other values I had with the SkyConnect, I don't have anymore the start problem of Z2M. I also flashed this Zigbee firmware : https://github.com/Nerivec/silabs-firmware-builder/releases/tag/v2024.6.2

@cyayon
Copy link

cyayon commented Nov 2, 2024

Hi,
I bought a SLZB-06M as a Zigbee coordinator.
i have upgraded to the last stable firmwares v2.5.6 and 20231030.
It is powered via POE (I tried different switches/cables).

i have some Ethernet connectivity issue and coordinator freeze/crashes.
After some days / hours the web interface is not more responding.
The ping sometimes always work but the web interface not after a few days/hours.

Disconnect / reconnect the Ethernet cable (power off/on), the web interface work again.
Tried to force the port speed (on the switch) to 100M full duplex, it works but there are CRC Ethernet errors. Return to auto speed, no more CRC.
Tried to change port switch and cable, same issue.
Of course, when the web interface fail, the tcp socket connection for zigbee2mqtt is also dead…
There are also lot of FCS Ethernet error on the switch port when the device is frozen.

I managed to dump logs via USB and https://www.anticyclone-systems.co.uk/aslwebterm.php

esp.emac: emac_esp32_transmit(229): insufficient TX buffer size E (62967041) esp.emac: emac_esp32_transmit(229): insufficient TX buffer size E (62967588) esp.emac: emac_esp32_transmit(229): insufficient TX buffer size E (62968588) esp.emac: emac_esp32_transmit(229): insufficient TX buffer size E (62969588) esp.emac: emac_esp32_transmit(229): insufficient TX buffer size E (62970588) esp.emac: emac_esp32_transmit(229): insufficient TX buffer size E (62974041) esp.emac: emac_esp32_transmit(229): insufficient TX buffer size E (62974588) esp.emac: emac_esp32_transmit(229): insufficient TX buffer size E (62975588) esp.emac: emac_esp32_transmit(229): insufficient TX buffer size E (62976588) esp.emac: emac_esp32_transmit(229): insufficient TX buffer size E (62977588) esp.emac: emac_esp32_transmit(229): insufficient TX buffer size E (62981041) esp.emac: emac_esp32_transmit(229): insufficient TX buffer size E (62981588) esp.emac: emac_esp32_transmit(229): insufficient TX buffer size E (62982588) esp.emac: emac_esp32_transmit(229): insufficient TX buffer size E (62983588) esp.emac: emac_esp32_trans

SMLIGHT support give the a 2.5.8 firmware to test but it was the same issue, after a few days, the adapter crash again.

Any idea ?
Thanks.

@brugalibre
Copy link

Are there any news? Like an updated firmware or an official statement in which the issue is officialy acknowledged?
I'm switching back from the SLZB-06M to the SLZB-06 since the ember integration is causing to much pain for which I simply do not have the time.
Two times a perfectly working network suddenly stoped working after a restart since the adapter could not be started anymore

@mrBobMusic
Copy link

Following

@Rainking80
Copy link

Following - have the same issue

1 similar comment
@gokaycagri
Copy link

Following - have the same issue

@clsergent
Copy link

Following - same issue...

@BenjaminMichaelis
Copy link

Following - bummer there are no consistent work arounds currently it seems.

@BenjaminMichaelis
Copy link

Following - bummer there are no consistent work arounds currently it seems.

Is there any information or help that can be provided to help resolve this @Nerivec? I'm not too familiar with this hardware so I'm not totally sure where to go next, but have debugged and tried what I can so far, but am happy to provide needed information.

@Nerivec
Copy link
Collaborator

Nerivec commented Dec 16, 2024

For the SLZB06/06M, SMLight has been working on fixing a bug introduced around Core 2.5.6 that causes the ESP to slow down to the point where it either crashes, or really messes up the Zigbee side (timeouts, errors, etc.). We've yet to receive feedback on whether it was fixed or not. Some users have had better result with 2.3.6 I believe, but that's about as much information as we have right now. That part is out of Z2M's control.

Some issues in this thread have been fixed, some not, it's a bit of a mix-of-things at this point.
We could use a recent debug log of Z2M, and the ESP (from SMLight interface), that would be helpful. We'll at least confirm if the issues point to that same ESP problem or not.
Can you also post what setup/hardware you are running Z2M on (HA, baremetal, PI, etc..), and specifically what RAM it has?

@Ra72xx
Copy link

Ra72xx commented Dec 16, 2024

I'm in the process of upgrading to an SLZB-07MG24, any chance that this more recent HW isn't suffering from this problems?

@Nerivec
Copy link
Collaborator

Nerivec commented Dec 16, 2024

@Ra72xx 07 isn't TCP-based, so no ESP side at all (no core firmware involved, just the serial driver on your machine).
I've been using the SLZB-07MG24 in testing for a while (8.0.2 firmware), no problem so far (as coordinator or as router). Granted, my test setup is more limited than a real network, but I do put it through far more than most users ever will in terms of reboots, edge cases, forced crashes, etc. 😉
The MG24 series offers quite a lot more in terms of specs, most networks should benefit (but especially larger/crowded ones).
For examples, SMLight SLZB-07MG24 has 2x the RAM from (most) previous adapters (MG21), TubesZB MGM24 has 4x the RAM. This should allow them to handle tougher scenario.

@Ra72xx
Copy link

Ra72xx commented Dec 16, 2024

Tbanks for the info. I'm using SkyConnect right now, but am suffering from various instabilities like the one here in this thread (which, however, seems to have gotten better recently), so I'm a bit hoping that the newer hardware will make my network more stable.

@takbo3000
Copy link

takbo3000 commented Dec 18, 2024

Following - same issue...
HA Core 2024.12.4 with zigbee2mqtt Addon 1.42.0-2 SLZB-06M

@Nerivec
Copy link
Collaborator

Nerivec commented Dec 18, 2024

Out of curiosity (I don't have the 06m, I cannot test it myself), has anyone tried the esphome firmware for this model instead of the core firmware for the ESP side?
https://smlight.tech/manual/slzb-06/guide/bluetooth-proxy/#poe-bluetooth-proxy-and-esphome
It's described for bluetooth proxing in SMLight docs, but you should be able to use it only for Zigbee. Ideally, you'd want to disable BT completely and compile a new firmware (using esphome directly or through HA):
https://github.com/smlight-dev/slzb-06-fw-esphome/blob/main/configs/zb-bt.yaml

For reference, here is an example with the MGM24 from TubesZB:
https://github.com/tube0013/tube_gateways/blob/main/models/current/tubeszb-efr32-MGM24/firmware/ESPHome/tubeszb-mgm24.yaml

@cairnsie13
Copy link

Following - hopefully a update soon.

@Leecavturbo
Copy link

Leecavturbo commented Dec 29, 2024

following after smlight install and z2m not starting ( with any adapter ezsp,ember or zstack ).
The 06 UI shows as z2m connected briefly on add-on startup so I know it’s pointed at the right address.
Latest core and z2m firmware.
Lan POE powered and co-ord mode set.

@takbo3000
Copy link

takbo3000 commented Dec 29, 2024

Hello everyone!
I can't explain the technical background. But maybe it will help someone.
After many hours of trying, I found the following solution for myself:

  • Raspberry Pi 4 Model B 4GB is not powerful enough for zigbee2mqtt edge with dev firmware --> addon freezes
  • zigbee2mqtt edge addon didn't work on my Raspi
  • Hardware change HP elitedesk G 800 i5 8500T 8GB RAM, it worked with the following setting:
    Proxmox/VM-Debian/HomeAssistant Firmware SLZB06M v2.6.8.dev25, Zigbee firmware revision: 20241127
    No other firmware combination worked with ember driver, everything tested.
    Summary: With Raspi no, Elitedesk yes. and only with the specified combination of edge, ember, core firmware and zigbee firmware. --> double check mqtt settings ;-)

@cairnsie13
Copy link

Hi takbo3000 thanks for the info, are you connected via ethernet or usb?

@takbo3000
Copy link

via IP/Ethernet

@Nerivec
Copy link
Collaborator

Nerivec commented Dec 29, 2024

Raspberry Pi 4 Model B 4GB is not powerful enough for zigbee2mqtt edge with dev firmware --> addon freezes

That should mostly depend on "what else is running", since Z2M itself consumes a fairly low amount of resources (70-100MB of RAM, which should be more than fine for these specs), but HA, and some addons (especially AI-related) can consume quite a lot, and large spikes in resources usage can affect overall stability.

Last I heard (before the holidays), the core firmware bug had not been identified by SMLight yet.
If anyone can test the esphome firmware instead of the core firmware, let me know. I can help via Discord if needed.

Note: Beware, proxmox has been linked to a few too many issues recently (confirmed or suspected), so, if setting up a new machine, you may want to look elsewhere. NIC issues. For USB users, passthrough also has issues, see this.

@cairnsie13
Copy link

Version 2.0 of z2m appears to have fixed the issue for me. I'm now running zigbee firmware revision: 20241127 and core firmware version: v2.3.6 with no issues via ethernet. Only updated today so unsure how stable it will be in the long run.

@asjapulk
Copy link

asjapulk commented Jan 5, 2025

Basically the same problem. Logs and conf #25537
Seems like I picked a wrong time for starting with Z2M..or wrong adapter :(

@cairnsie13
Copy link

Mine crashed several hours later.

@Nerivec
Copy link
Collaborator

Nerivec commented Jan 6, 2025

I built some ESPHome firmware for a couple of adapters. I have only tested the TubesZB MGM24, I do not have the SLZB06M. The SLZB06M firmware is modeled from the TubesZB one (with a few extras). If someone is willing & able to test it to replace the core firmware, let me know.

https://nerivec.github.io/esphome-firmware-builder/ (web flasher via USB, similar to the SMLight one for core firmware)
You can check the details of the build in the manifest.
It has a minimal web server accessible at the IP address with a few useful sensors/buttons, and the port for Z2M connection is 6638, example: tcp://192.168.1.10:6638.
(configuration was pulled and adapted from smlight repo)

If you want to test this, you can find me on Discord if you want some help or can provide some detailed feedback (can DM me from the zigbee2mqtt server).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
ember Issues related to ember driver problem Something isn't working
Projects
None yet
Development

No branches or pull requests