search

Koenkk / zigbee2mqtt

Zigbee 🐝 to MQTT bridge 🌉, get rid of your proprietary Zigbee bridges 🔨
https://www.zigbee2mqtt.io
GNU General Public License v3.0
12.14k stars 1.68k forks source link

Zigbee2MQTT HOST_FATAL_ERROR with newly flashed Sonoff Dongle V2 #24726

Open Rainking80 opened 2 days ago

Rainking80 commented 2 days ago

What happened?

I flashed my Sonoff Dongle E V2 to the latest FW: ncp-uart-hw-v7.4.2.0-zbdonglee-115200.gbl and now i see this endlessly repeating:

[17:26:50] INFO: Preparing to start... [17:26:50] INFO: Socat not enabled [17:26:50] INFO: Starting Zigbee2MQTT... Starting Zigbee2MQTT without watchdog. [2024-11-11 17:26:52] info: z2m: Logging to console, file (filename: log.log) [2024-11-11 17:26:52] info: z2m: Starting Zigbee2MQTT version 1.41.0 (commit #unknown) [2024-11-11 17:26:52] info: z2m: Starting zigbee-herdsman (2.1.7) [2024-11-11 17:26:52] info: zh:ember: Using default stack config. [2024-11-11 17:26:52] info: zh:ember: ======== Ember Adapter Starting ======== [2024-11-11 17:26:52] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-11-11 17:26:52] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-11-11 17:26:52] info: zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control. [2024-11-11 17:26:52] info: zh:ember:uart:ash: Serial port opened [2024-11-11 17:26:52] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-11-11 17:26:55] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-11-11 17:26:55] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-11-11 17:26:57] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-11-11 17:26:57] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-11-11 17:27:00] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-11-11 17:27:00] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-11-11 17:27:02] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-11-11 17:27:02] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-11-11 17:27:05] error: z2m: Error while starting zigbee-herdsman [2024-11-11 17:27:05] error: z2m: Failed to start zigbee [2024-11-11 17:27:05] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions [2024-11-11 17:27:05] error: z2m: Exiting... [2024-11-11 17:27:05] error: z2m: Error: Failed to start EZSP layer with status=HOST_FATAL_ERROR. at EmberAdapter.initEzsp (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:684:19) at EmberAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1598:24) at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:137:29) at Zigbee.start (/app/lib/zigbee.ts:69:27) at Controller.start (/app/lib/controller.ts:161:27) at start (/app/index.js:154:5)

my zigbee2mqtt config: serial: port: /dev/serial/by-id/usb-Itead_Sonoff_Zigbee_3.0_USB_Dongle_Plus_V2_f45097c0c312ef118bf96db8bf9df066-if00-port0 baudrate: 115200 adapter: ember zigbee_herdsman_debug: true

sometimes the error is a bit different:

[17:48:12] INFO: Preparing to start... [17:48:12] INFO: Socat not enabled [17:48:12] INFO: Starting Zigbee2MQTT... Starting Zigbee2MQTT without watchdog. [2024-11-11 17:48:14] info: z2m: Logging to console, file (filename: log.log) [2024-11-11 17:48:14] info: z2m: Starting Zigbee2MQTT version 1.41.0 (commit #unknown) [2024-11-11 17:48:14] info: z2m: Starting zigbee-herdsman (2.1.7) [2024-11-11 17:48:14] info: zh:ember: Using default stack config. [2024-11-11 17:48:14] info: zh:ember: ======== Ember Adapter Starting ======== [2024-11-11 17:48:14] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-11-11 17:48:14] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-11-11 17:48:14] info: zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control. [2024-11-11 17:48:14] info: zh:ember:uart:ash: Serial port opened [2024-11-11 17:48:14] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-11-11 17:48:17] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-11-11 17:48:17] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-11-11 17:48:19] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-11-11 17:48:19] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-11-11 17:48:22] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-11-11 17:48:22] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-11-11 17:48:24] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-11-11 17:48:24] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-11-11 17:48:26] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-11-11 17:48:26] info: zh:ember:uart:ash: ======== ASH started ======== [2024-11-11 17:48:26] info: zh:ember:ezsp: ======== EZSP started ======== [2024-11-11 17:48:40] error: zh:ember:ezsp: ERROR Transaction failure; status=ASH_ERROR_TIMEOUTS. Last Frame: [FRAME: ID=0:"VERSION" Seq=0 Len=0]. [2024-11-11 17:48:40] error: zh:ember: Adapter fatal error: ASH_ERROR_TIMEOUTS [2024-11-11 17:48:40] error: z2m: Error while starting zigbee-herdsman [2024-11-11 17:48:40] error: z2m: Failed to start zigbee [2024-11-11 17:48:40] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions [2024-11-11 17:48:40] error: z2m: Exiting... [2024-11-11 17:48:40] error: z2m: Error: ASH_ERROR_TIMEOUTS at Ezsp.ezspVersion (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:1408:19) at EmberAdapter.emberVersion (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1412:63) at EmberAdapter.initEzsp (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:688:9) at EmberAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1598:24) at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:137:29) at Zigbee.start (/app/lib/zigbee.ts:69:27) at Controller.start (/app/lib/controller.ts:161:27) at start (/app/index.js:154:5)

i tried to fix that since 3 days and i am out of ideas. If you have any suggestion what i can try please help me :)

What did you expect to happen?

Zigbee2MQTT starting sucessfully

How to reproduce it (minimal and precise)

No response

Zigbee2MQTT version

1.41.0-1

Adapter firmware version

ncp-uart-hw-v7.4.2.0-zbdonglee-115200

Adapter

Sonoff Zigbee 3 Dongle E V2

Setup

Home Assistant OS on Pi5

Debug log

No response

Ricc68 commented 2 days ago

Very similar to the issue #23282 I am experiencing.

Rainking80 commented 2 days ago

@Ricc68 thanks for linking the issue! Unfortunately restart wont solve the issue at my system. I even tried ZHA and Z2M and deleted all configs, reinstalled plugins, down graded HA Core.... but still no luck. used skyconnect and sonoff zigbee 3 E Dongle V2.

further downgrading the radio stick will be next.

Ricc68 commented 2 days ago

... used skyconnect and sonoff zigbee 3 E Dongle V2.

Are you having the same issue with both?

Rainking80 commented 2 days ago

yes, seems to be something with HA OS. Started about 2 weeks ago on both of my home assistant machines(pi4 and pi5). I tried downgrading of my HA OS version, but problem still exists.

Rainking80 commented 2 days ago

after a full shutdown and reboot, i see sometimes more progress in the log:

[22:42:39] INFO: Preparing to start... [22:42:39] INFO: Socat not enabled [22:42:39] INFO: Starting Zigbee2MQTT... Starting Zigbee2MQTT without watchdog. [2024-11-11 22:42:42] info: z2m: Logging to console, file (filename: log.log) [2024-11-11 22:42:42] info: z2m: Starting Zigbee2MQTT version 1.41.0-dev (commit #22e13c5) [2024-11-11 22:42:42] info: z2m: Starting zigbee-herdsman (2.1.7) [2024-11-11 22:42:42] info: zh:ember: Using default stack config. [2024-11-11 22:42:42] info: zh:ember: ======== Ember Adapter Starting ======== [2024-11-11 22:42:42] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-11-11 22:42:42] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-11-11 22:42:42] info: zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control. [2024-11-11 22:42:42] info: zh:ember:uart:ash: Serial port opened [2024-11-11 22:42:42] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-11-11 22:42:43] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-11-11 22:42:43] info: zh:ember:uart:ash: ======== ASH started ======== [2024-11-11 22:42:43] info: zh:ember:ezsp: ======== EZSP started ======== [2024-11-11 22:42:43] info: zh:ember: Adapter EZSP protocol version (13) lower than Host. Switched. [2024-11-11 22:42:43] info: zh:ember: Adapter version info: {"ezsp":13,"revision":"7.4.1 [GA]","build":0,"major":7,"minor":4,"patch":1,"special":0,"type":170} [2024-11-11 22:42:43] info: zh:ember: [STACK STATUS] Network up. [2024-11-11 22:42:43] info: zh:ember: [INIT TC] Adapter network does not match config. Leaving network... [2024-11-11 22:42:44] info: zh:ember: [STACK STATUS] Network down. [2024-11-11 22:42:44] info: zh:ember: [INIT TC] No valid backup found. [2024-11-11 22:42:44] info: zh:ember: [INIT TC] Forming from config. [2024-11-11 22:42:44] info: zh:ember: [INIT FORM] Forming new network with: {"panId":61483,"extendedPanId":[240,167,41,254,166,82,163,232],"radioTxPower":5,"radioChannel":11,"joinMethod":0,"nwkManagerId":0,"nwkUpdateId":0,"channels":134215680} [2024-11-11 22:42:44] info: zh:ember: [STACK STATUS] Network up. [2024-11-11 22:42:44] info: zh:ember: [INIT FORM] New network formed! [2024-11-11 22:42:44] info: zh:ember: [CONCENTRATOR] Started source route discovery. 1248ms until next broadcast. [2024-11-11 22:42:44] info: zh:controller: Wrote coordinator backup to '/config/zigbee2mqtt/coordinator_backup.json' [2024-11-11 22:42:59] error: zh:ember:ezsp: ERROR Transaction failure; status=ASH_ERROR_TIMEOUTS. Last Frame: [FRAME: ID=276:"EXPORT_KEY" Seq=43 Len=25]. [2024-11-11 22:42:59] error: zh:ember: Adapter fatal error: ASH_ERROR_TIMEOUTS [2024-11-11 22:42:59] info: zh:ember:uart:ash: ASH COUNTERS since last clear: [2024-11-11 22:42:59] info: zh:ember:uart:ash: Total frames: RX=48, TX=94 [2024-11-11 22:42:59] info: zh:ember:uart:ash: Cancelled : RX=0, TX=0 [2024-11-11 22:42:59] info: zh:ember:uart:ash: DATA frames : RX=47, TX=45 [2024-11-11 22:42:59] info: zh:ember:uart:ash: DATA bytes : RX=428, TX=505 [2024-11-11 22:42:59] info: zh:ember:uart:ash: Retry frames: RX=0, TX=0 [2024-11-11 22:42:59] info: zh:ember:uart:ash: ACK frames : RX=0, TX=48 [2024-11-11 22:42:59] info: zh:ember:uart:ash: NAK frames : RX=0, TX=0 [2024-11-11 22:42:59] info: zh:ember:uart:ash: nRdy frames : RX=0, TX=0 [2024-11-11 22:42:59] info: zh:ember:uart:ash: CRC errors : RX=0 [2024-11-11 22:42:59] info: zh:ember:uart:ash: Comm errors : RX=0 [2024-11-11 22:42:59] info: zh:ember:uart:ash: Length < minimum: RX=0 [2024-11-11 22:42:59] info: zh:ember:uart:ash: Length > maximum: RX=0 [2024-11-11 22:42:59] info: zh:ember:uart:ash: Bad controls : RX=0 [2024-11-11 22:42:59] info: zh:ember:uart:ash: Bad lengths : RX=0 [2024-11-11 22:42:59] info: zh:ember:uart:ash: Bad ACK numbers : RX=0 [2024-11-11 22:42:59] info: zh:ember:uart:ash: Out of buffers : RX=0 [2024-11-11 22:42:59] info: zh:ember:uart:ash: Retry dupes : RX=0 [2024-11-11 22:42:59] info: zh:ember:uart:ash: Out of sequence : RX=0 [2024-11-11 22:42:59] info: zh:ember:uart:ash: ACK timeouts : RX=0 [2024-11-11 22:42:59] error: z2m: Error while starting zigbee-herdsman [2024-11-11 22:42:59] error: z2m: Failed to start zigbee [2024-11-11 22:42:59] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions [2024-11-11 22:42:59] error: z2m: Exiting... [2024-11-11 22:42:59] error: z2m: Error: ASH_ERROR_TIMEOUTS at Ezsp.ezspSendUnicast (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:4817:19) at /app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1917:41 at Queue.execute (/app/node_modules/zigbee-herdsman/src/utils/queue.ts:36:20) at EmberAdapter.sendZdo (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1867:16) at Device.updateActiveEndpoints (/app/node_modules/zigbee-herdsman/src/controller/model/device.ts:1067:26) at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:206:13) at Zigbee.start (/app/lib/zigbee.ts:69:27) at Controller.start (/app/lib/controller.ts:161:27) at start (/app/index.js:154:5)

Nerivec commented 14 hours ago

What was the previous version on your adapter? Since you appear to have no previous config in Z2M (nothing to backup, so it's easy), I'd suggest you try clearing the NVM3, either with ember-zli or by flashing the nvm3_initfile (same result). At the very least, it will eliminate the possibility of a mismatch in the firmware that could be creating troubles (can happen after jumping version like v6 > v7).

Then make sure you flash the latest 7.4 version: https://github.com/darkxst/silabs-firmware-builder/raw/refs/heads/main/firmware_builds/zbdonglee/ncp-uart-hw-v7.4.4.0-zbdonglee-115200.gbl (or you can go to version 8 too)

Rainking80 commented 9 hours ago

hey, thanks i tried ember-zli but i cannot interact with the bootloader (the rest works)

image

will try the flashing now:

image

Rainking80 commented 9 hours ago

damn, still doing the thing:

[17:55:10] INFO: Preparing to start...
[17:55:10] INFO: Socat not enabled
[17:55:10] INFO: Starting Zigbee2MQTT...
Starting Zigbee2MQTT without watchdog.
[2024-11-13 17:55:12] info:     z2m: Logging to console, file (filename: log.log)
[2024-11-13 17:55:12] info:     z2m: Starting Zigbee2MQTT version 1.41.0 (commit #unknown)
[2024-11-13 17:55:12] info:     z2m: Starting zigbee-herdsman (2.1.7)
[2024-11-13 17:55:13] info:     zh:ember: Using default stack config.
[2024-11-13 17:55:13] info:     zh:ember: ======== Ember Adapter Starting ========
[2024-11-13 17:55:13] info:     zh:ember:ezsp: ======== EZSP starting ========
[2024-11-13 17:55:13] info:     zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-11-13 17:55:13] info:     zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control.
[2024-11-13 17:55:13] info:     zh:ember:uart:ash: Serial port opened
[2024-11-13 17:55:13] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-11-13 17:55:15] info:     zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-11-13 17:55:15] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-11-13 17:55:18] info:     zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-11-13 17:55:18] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-11-13 17:55:20] info:     zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-11-13 17:55:20] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-11-13 17:55:23] info:     zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-11-13 17:55:23] info:     zh:ember:uart:ash: ======== ASH starting ========
[2024-11-13 17:55:25] error:    z2m: Error while starting zigbee-herdsman
[2024-11-13 17:55:25] error:    z2m: Failed to start zigbee
[2024-11-13 17:55:25] error:    z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions
[2024-11-13 17:55:25] error:    z2m: Exiting...
[2024-11-13 17:55:25] error:    z2m: Error: Failed to start EZSP layer with status=HOST_FATAL_ERROR.
    at EmberAdapter.initEzsp (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:684:19)
    at EmberAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1598:24)
    at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:137:29)
    at Zigbee.start (/app/lib/zigbee.ts:69:27)
    at Controller.start (/app/lib/controller.ts:161:27)
    at start (/app/index.js:154:5)
Nerivec commented 8 hours ago

That zlib error with ember-zli likely means you are using an older NodeJS version (it requires >=20.15.0).

Make sure to always use Software flow control, rtscts: false with Dongle-E, it does not support hardware flow control. I saw you set it as true in ember-zli screenshot.

That looping of ASH Adapter reset usually means one of the following:

Basically, it can't communicate to the adapter properly (or at all).

After flashing the NVM3, did you re-flash one of the firmware files I linked before? Can you try running with log_level: debug in your configuration.yaml so I can get some more details? You can find me on Discord, DM me after joining zigbee2mqtt server, if you prefer sharing the logs that way.

advanced:
  log_level: debug
Rainking80 commented 7 hours ago
here ist the log_level: debug: ``` [19:19:34] INFO: Preparing to start... [19:19:34] INFO: Socat not enabled [19:19:34] INFO: Starting Zigbee2MQTT... Starting Zigbee2MQTT without watchdog. [2024-11-13 19:19:36] info: z2m: Logging to console, file (filename: log.log) [2024-11-13 19:19:36] debug: z2m: Loaded state from file /config/zigbee2mqtt/state.json [2024-11-13 19:19:36] info: z2m: Starting Zigbee2MQTT version 1.41.0 (commit #unknown) [2024-11-13 19:19:36] debug: z2m: sd-notify loaded [2024-11-13 19:19:36] info: z2m: Starting zigbee-herdsman (2.1.7) [2024-11-13 19:19:36] debug: z2m: Using zigbee-herdsman with settings: '"{\"network\":{\"panID\":1321,\"extendedPanID\":[23,58,119,75,209,77,211,4],\"channelList\":[25],\"networkKey\":\"HIDDEN\"},\"databasePath\":\"/config/zigbee2mqtt/database.db\",\"databaseBackupPath\":\"/config/zigbee2mqtt/database.db.backup\",\"backupPath\":\"/config/zigbee2mqtt/coordinator_backup.json\",\"serialPort\":{\"baudRate\":115200,\"rtscts\":false,\"path\":\"/dev/serial/by-id/usb-Itead_Sonoff_Zigbee_3.0_USB_Dongle_Plus_V2_f45097c0c312ef118bf96db8bf9df066-if00-port0\",\"adapter\":\"ezsp\"},\"adapter\":{\"disableLED\":false}}"' [2024-11-13 19:19:36] debug: zh:ezsp: Adapter concurrent: 8 [2024-11-13 19:19:36] debug: zh:controller: Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":"HIDDEN","panID":1321,"extendedPanID":[23,58,119,75,209,77,211,4],"channelList":[25]},"serialPort":{"baudRate":115200,"rtscts":false,"path":"/dev/serial/by-id/usb-Itead_Sonoff_Zigbee_3.0_USB_Dongle_Plus_V2_f45097c0c312ef118bf96db8bf9df066-if00-port0","adapter":"ezsp"},"adapter":{"disableLED":false},"databasePath":"/config/zigbee2mqtt/database.db","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","backupPath":"/config/zigbee2mqtt/coordinator_backup.json"}' [2024-11-13 19:19:36] warning: zh:ezsp: 'ezsp' driver is deprecated and will only remain to provide support for older firmware (pre 7.4.x). Migration to 'ember' is recommended. If using Zigbee2MQTT see https://github.com/Koenkk/zigbee2mqtt/discussions/21462 [2024-11-13 19:19:36] debug: zh:ezsp:uart: RTS/CTS config is off, enabling software flow control. [2024-11-13 19:19:36] debug: zh:ezsp:uart: Opening SerialPort with {"path":"/dev/serial/by-id/usb-Itead_Sonoff_Zigbee_3.0_USB_Dongle_Plus_V2_f45097c0c312ef118bf96db8bf9df066-if00-port0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true} [2024-11-13 19:19:36] debug: zh:ezsp:uart: Serialport opened [2024-11-13 19:19:36] debug: zh:ezsp:uart: Uart reseting [2024-11-13 19:19:36] debug: zh:ezsp:uart: --> Write reset [2024-11-13 19:19:36] debug: zh:ezsp:uart: --> [1ac038bc7e] [2024-11-13 19:19:36] debug: zh:ezsp:uart: -?- waiting reset [2024-11-13 19:19:46] error: zh:ezsp:uart: --> Error: Error: {"sequence":-1} after 10000ms [2024-11-13 19:19:46] error: zh:ezsp:ezsp: Connection attempt 1 error: Error: Failure to connect [2024-11-13 19:19:46] debug: zh:ezsp:uart: Port closed. Error? null [2024-11-13 19:19:46] debug: zh:ezsp:ezsp: onSerialClose() [2024-11-13 19:19:46] debug: zh:ezsp:driv: onEzspClose() [2024-11-13 19:19:46] debug: zh:ezsp: onDriverClose() [2024-11-13 19:19:51] debug: zh:ezsp:ezsp: Next attempt 2 [2024-11-13 19:19:51] debug: zh:ezsp:uart: RTS/CTS config is off, enabling software flow control. [2024-11-13 19:19:51] debug: zh:ezsp:uart: Opening SerialPort with {"path":"/dev/serial/by-id/usb-Itead_Sonoff_Zigbee_3.0_USB_Dongle_Plus_V2_f45097c0c312ef118bf96db8bf9df066-if00-port0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true} [2024-11-13 19:19:51] debug: zh:ezsp:uart: Serialport opened [2024-11-13 19:19:51] debug: zh:ezsp:uart: Uart reseting [2024-11-13 19:19:51] debug: zh:ezsp:uart: --> Write reset [2024-11-13 19:19:51] debug: zh:ezsp:uart: --> [1ac038bc7e] [2024-11-13 19:19:51] debug: zh:ezsp:uart: -?- waiting reset [2024-11-13 19:20:01] error: zh:ezsp:uart: --> Error: Error: {"sequence":-1} after 10000ms [2024-11-13 19:20:01] error: zh:ezsp:ezsp: Connection attempt 2 error: Error: Failure to connect [2024-11-13 19:20:01] debug: zh:ezsp:uart: Port closed. Error? null [2024-11-13 19:20:01] debug: zh:ezsp:ezsp: onSerialClose() [2024-11-13 19:20:01] debug: zh:ezsp:driv: onEzspClose() [2024-11-13 19:20:01] debug: zh:ezsp: onDriverClose() [2024-11-13 19:20:11] debug: zh:ezsp:ezsp: Next attempt 3 [2024-11-13 19:20:11] debug: zh:ezsp:uart: RTS/CTS config is off, enabling software flow control. [2024-11-13 19:20:11] debug: zh:ezsp:uart: Opening SerialPort with {"path":"/dev/serial/by-id/usb-Itead_Sonoff_Zigbee_3.0_USB_Dongle_Plus_V2_f45097c0c312ef118bf96db8bf9df066-if00-port0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true} [2024-11-13 19:20:11] debug: zh:ezsp:uart: Serialport opened [2024-11-13 19:20:11] debug: zh:ezsp:uart: Uart reseting [2024-11-13 19:20:11] debug: zh:ezsp:uart: --> Write reset [2024-11-13 19:20:11] debug: zh:ezsp:uart: --> [1ac038bc7e] [2024-11-13 19:20:11] debug: zh:ezsp:uart: -?- waiting reset [2024-11-13 19:20:12] debug: zh:ezsp:uart: <-- [c1020b0a527e] [2024-11-13 19:20:12] debug: zh:ezsp:uart: <-- RSTACK c1020b0a527e [2024-11-13 19:20:12] debug: zh:ezsp:uart: RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e [2024-11-13 19:20:12] debug: zh:ezsp:uart: <-- RSTACK c1020b0a527e [2024-11-13 19:20:12] debug: zh:ezsp:uart: RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e [2024-11-13 19:20:12] debug: zh:ezsp:uart: <-- RSTACK c1020b0a527e [2024-11-13 19:20:12] debug: zh:ezsp:uart: RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e [2024-11-13 19:20:12] debug: zh:ezsp:uart: -+- waiting reset success [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: ==> version: {"desiredProtocolVersion":4} [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: ==> {"_cls_":"version","_id_":0,"_isRequest_":true,"desiredProtocolVersion":4} [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> DATA (0,0,0): 00000004 [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [004221a850ed2c7e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: -?- waiting (1) [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- [0142a1a8592855c6a6c87e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (0,1,0): 0142a1a8592855c6a6c87e [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> ACK (1) [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [8160597e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- ACK (1): 0142a1a8592855c6a6c87e [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: <== Frame: 0080000d024074 [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: <== 0x0: {"_cls_":"version","_id_":0,"_isRequest_":false,"protocolVersion":13,"stackType":2,"stackVersion":29760} [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (0,1,0): 0142a1a8592855c6a6c87e [2024-11-13 19:20:14] debug: zh:ezsp:uart: Unexpected DATA packet sequence 0 | 1: reject condition [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [a1443b7e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (0,1,0): 0142a1a8592855c6a6c87e [2024-11-13 19:20:14] debug: zh:ezsp:uart: Unexpected DATA packet sequence 0 | 1: reject condition [2024-11-13 19:20:14] debug: zh:ezsp:uart: -+- waiting (1) success [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: Switching to eszp version 13 [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: ==> version: {"desiredProtocolVersion":13} [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: ==> {"_cls_":"version","_id_":0,"_isRequest_":true,"desiredProtocolVersion":13} [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> DATA (1,1,0): 01000100000d [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [7d314321a9542a7d3899da7e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: -?- waiting (2) [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- [1243a1a9542a7d38b019e0ea307e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (1,2,0): 1243a1a9542a18b019e0ea307e [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> ACK (2) [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [82503a7e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- ACK (2): 1243a1a9542a18b019e0ea307e [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: <== Frame: 01800100000d024074 [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: <== 0x0: {"_cls_":"version","_id_":0,"_isRequest_":false,"protocolVersion":13,"stackType":2,"stackVersion":29760} [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (1,2,0): 1243a1a9542a18b019e0ea307e [2024-11-13 19:20:14] debug: zh:ezsp:uart: Unexpected DATA packet sequence 1 | 2: reject condition [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [a274587e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (1,2,0): 1243a1a9542a18b019e0ea307e [2024-11-13 19:20:14] debug: zh:ezsp:uart: Unexpected DATA packet sequence 1 | 2: reject condition [2024-11-13 19:20:14] debug: zh:ezsp:uart: -+- waiting (2) success [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_TC_REJOINS_USING_WELL_KNOWN_KEY_TIMEOUT_S = 90 [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":56,"value":90} [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":56,"value":90} [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> DATA (2,2,0): 0200015300385a00 [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [224021a9072a2de8595e057e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: -?- waiting (3) [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- [2340a1a9072a159ab77e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (2,3,0): 2340a1a9072a159ab77e [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> ACK (3) [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [83401b7e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- ACK (3): 2340a1a9072a159ab77e [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: <== Frame: 028001530000 [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (2,3,0): 2340a1a9072a159ab77e [2024-11-13 19:20:14] debug: zh:ezsp:uart: Unexpected DATA packet sequence 2 | 3: reject condition [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [a364797e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (2,3,0): 2340a1a9072a159ab77e [2024-11-13 19:20:14] debug: zh:ezsp:uart: Unexpected DATA packet sequence 2 | 3: reject condition [2024-11-13 19:20:14] debug: zh:ezsp:uart: -+- waiting (3) success [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_TRUST_CENTER_ADDRESS_CACHE_SIZE = 2 [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":25,"value":2} [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":25,"value":2} [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> DATA (3,3,0): 0300015300190200 [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [334121a9072a0cb05997eb7e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: -?- waiting (4) [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- [3441a1a9072a15f1287e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (3,4,0): 3441a1a9072a15f1287e [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> ACK (4) [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [8430fc7e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- ACK (4): 3441a1a9072a15f1287e [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: <== Frame: 038001530000 [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (3,4,0): 3441a1a9072a15f1287e [2024-11-13 19:20:14] debug: zh:ezsp:uart: Unexpected DATA packet sequence 3 | 4: reject condition [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [a4149e7e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (3,4,0): 3441a1a9072a15f1287e [2024-11-13 19:20:14] debug: zh:ezsp:uart: Unexpected DATA packet sequence 3 | 4: reject condition [2024-11-13 19:20:14] debug: zh:ezsp:uart: -+- waiting (4) success [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_FRAGMENT_DELAY_MS = 50 [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":29,"value":50} [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":29,"value":50} [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> DATA (4,4,0): 04000153001d3200 [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [444621a9072a08805993d67e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: -?- waiting (5) [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- [4546a1a9072a1505697e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (4,5,0): 4546a1a9072a1505697e [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> ACK (5) [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [8520dd7e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- ACK (5): 4546a1a9072a1505697e [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: <== Frame: 048001530000 [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (4,5,0): 4546a1a9072a1505697e [2024-11-13 19:20:14] debug: zh:ezsp:uart: Unexpected DATA packet sequence 4 | 5: reject condition [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [a504bf7e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (4,5,0): 4546a1a9072a1505697e [2024-11-13 19:20:14] debug: zh:ezsp:uart: Unexpected DATA packet sequence 4 | 5: reject condition [2024-11-13 19:20:14] debug: zh:ezsp:uart: -+- waiting (5) success [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_PAN_ID_CONFLICT_REPORT_THRESHOLD = 2 [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":34,"value":2} [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":34,"value":2} [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> DATA (5,5,0): 0500015300220200 [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [554721a9072a37b05980d97e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: -?- waiting (6) [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- [5647a1a9072a15af307e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (5,6,0): 5647a1a9072a15af307e [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> ACK (6) [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [8610be7e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- ACK (6): 5647a1a9072a15af307e [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: <== Frame: 058001530000 [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (5,6,0): 5647a1a9072a15af307e [2024-11-13 19:20:14] debug: zh:ezsp:uart: Unexpected DATA packet sequence 5 | 6: reject condition [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [a634dc7e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: <-- DATA (5,6,0): 5647a1a9072a15af307e [2024-11-13 19:20:14] debug: zh:ezsp:uart: Unexpected DATA packet sequence 5 | 6: reject condition [2024-11-13 19:20:14] debug: zh:ezsp:uart: -+- waiting (6) success [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_APPLICATION_ZDO_FLAGS = 3 [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":42,"value":3} [2024-11-13 19:20:14] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":42,"value":3} [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> DATA (6,6,0): 06000153002a0300 [2024-11-13 19:20:14] debug: zh:ezsp:uart: --> [664421a9072a3fb1590b7a7e] [2024-11-13 19:20:14] debug: zh:ezsp:uart: -?- waiting (7) [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- [6f44a1a9072a157d33917e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- DATA (6,7,1): 6f44a1a9072a1513917e [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> ACK (7) [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> [87009f7e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- ACK (7): 6f44a1a9072a1513917e [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: <== Frame: 068001530000 [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- DATA (6,7,1): 6f44a1a9072a1513917e [2024-11-13 19:20:15] debug: zh:ezsp:uart: Unexpected DATA packet sequence 6 | 7: packet replay [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> ACK (7) [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> [87009f7e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- ACK (7): 6f44a1a9072a1513917e [2024-11-13 19:20:15] debug: zh:ezsp:uart: Skipping the packet as repeated (7) [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- DATA (6,7,1): 6f44a1a9072a1513917e [2024-11-13 19:20:15] debug: zh:ezsp:uart: Unexpected DATA packet sequence 6 | 7: packet replay [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> ACK (7) [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> [87009f7e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- ACK (7): 6f44a1a9072a1513917e [2024-11-13 19:20:15] debug: zh:ezsp:uart: Skipping the packet as repeated (7) [2024-11-13 19:20:15] debug: zh:ezsp:uart: -+- waiting (7) success [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_INDIRECT_TRANSMISSION_TIMEOUT = 7680 [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":18,"value":7680} [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":18,"value":7680} [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> DATA (7,7,0): 070001530012001e [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> [774521a9072a07b2473edc7e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: -?- waiting (0) [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- [7045a1a9072a15eba37e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- DATA (7,0,0): 7045a1a9072a15eba37e [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> ACK (0) [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> [8070787e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- ACK (0): 7045a1a9072a15eba37e [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: <== Frame: 078001530000 [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- DATA (7,0,0): 7045a1a9072a15eba37e [2024-11-13 19:20:15] debug: zh:ezsp:uart: Unexpected DATA packet sequence 7 | 0: reject condition [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> [a0547d3a7e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- DATA (7,0,0): 7045a1a9072a15eba37e [2024-11-13 19:20:15] debug: zh:ezsp:uart: Unexpected DATA packet sequence 7 | 0: reject condition [2024-11-13 19:20:15] debug: zh:ezsp:uart: -+- waiting (0) success [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_END_DEVICE_POLL_TIMEOUT = 14 [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":19,"value":14} [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":19,"value":14} [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> DATA (0,0,0): 0800015300130e00 [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> [004a21a9072a06bc597d3aae7e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: -?- waiting (1) [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- [014aa1a9072a1512a07e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- DATA (0,1,0): 014aa1a9072a1512a07e [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> ACK (1) [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> [8160597e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- ACK (1): 014aa1a9072a1512a07e [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: <== Frame: 088001530000 [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- DATA (0,1,0): 014aa1a9072a1512a07e [2024-11-13 19:20:15] debug: zh:ezsp:uart: Unexpected DATA packet sequence 0 | 1: reject condition [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> [a1443b7e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- DATA (0,1,0): 014aa1a9072a1512a07e [2024-11-13 19:20:15] debug: zh:ezsp:uart: Unexpected DATA packet sequence 0 | 1: reject condition [2024-11-13 19:20:15] debug: zh:ezsp:uart: -+- waiting (1) success [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_SECURITY_LEVEL = 5 [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":13,"value":5} [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":13,"value":5} [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> DATA (1,1,0): 09000153000d0500 [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> [7d314b21a9072a7d38b75961387e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: -?- waiting (2) [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- [124ba1a9072a15b8f97e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- DATA (1,2,0): 124ba1a9072a15b8f97e [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> ACK (2) [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> [82503a7e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- ACK (2): 124ba1a9072a15b8f97e [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: <== Frame: 098001530000 [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- DATA (1,2,0): 124ba1a9072a15b8f97e [2024-11-13 19:20:15] debug: zh:ezsp:uart: Unexpected DATA packet sequence 1 | 2: reject condition [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> [a274587e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: <-- DATA (1,2,0): 124ba1a9072a15b8f97e [2024-11-13 19:20:15] debug: zh:ezsp:uart: Unexpected DATA packet sequence 1 | 2: reject condition [2024-11-13 19:20:15] debug: zh:ezsp:uart: -+- waiting (2) success [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_STACK_PROFILE = 2 [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":12,"value":2} [2024-11-13 19:20:15] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":12,"value":2} [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> DATA (2,2,0): 0a000153000c0200 [2024-11-13 19:20:15] debug: zh:ezsp:uart: --> [224821a9072a19b059deac7e] [2024-11-13 19:20:15] debug: zh:ezsp:uart: -?- waiting (3) [2024-11-13 19:20:19] error: zh:ezsp:uart: --> Error: Error: {"sequence":3} after 4000ms [2024-11-13 19:20:19] error: zh:ezsp:uart: -!- break waiting (3) [2024-11-13 19:20:19] error: zh:ezsp:uart: Can't send DATA frame (2,2,0): 0a000153000c0200 [2024-11-13 19:20:20] debug: zh:ezsp:uart: ->> DATA (2,2,1): 0a000153000c0200 [2024-11-13 19:20:20] debug: zh:ezsp:uart: --> [2a4821a9072a19b059f7537e] [2024-11-13 19:20:20] debug: zh:ezsp:uart: -?- rewaiting (3) [2024-11-13 19:20:20] debug: zh:ezsp:uart: <-- [83401b7e] [2024-11-13 19:20:20] debug: zh:ezsp:uart: <-- ACK (3): 83401b7e [2024-11-13 19:20:20] debug: zh:ezsp:uart: <-- ACK (3): 83401b7e [2024-11-13 19:20:20] debug: zh:ezsp:uart: <-- ACK (3): 83401b7e [2024-11-13 19:20:20] debug: zh:ezsp:uart: -+- rewaiting (3) success [2024-11-13 19:20:24] debug: zh:ezsp:ezsp: Time to watchdog ... 0 [2024-11-13 19:20:24] debug: zh:ezsp:ezsp: ==> nop: undefined [2024-11-13 19:20:30] debug: zh:ezsp:ezsp: ==> {"_cls_":"nop","_id_":5,"_isRequest_":true} [2024-11-13 19:20:30] debug: zh:ezsp:uart: --> DATA (3,2,0): 0b00010500 [2024-11-13 19:20:30] debug: zh:ezsp:uart: --> [324921a9512ac9997e] [2024-11-13 19:20:30] debug: zh:ezsp:uart: -?- waiting (4) [2024-11-13 19:20:30] error: zh:ezsp:ezsp: setConfigurationValue(12, 2) error: Error: Failure send setConfigurationValue:{"type":"Buffer","data":[10,0,1,83,0,12,2,0]} [2024-11-13 19:20:30] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_FRAGMENT_WINDOW_SIZE = 1 [2024-11-13 19:20:30] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":28,"value":1} [2024-11-13 19:20:30] debug: zh:ezsp:uart: <-- [c20251a8bd7e] [2024-11-13 19:20:30] debug: zh:ezsp:uart: <-- Error c20251a8bd7e [2024-11-13 19:20:30] debug: zh:ezsp:uart: Uart reseting [2024-11-13 19:20:30] debug: zh:ezsp:uart: --> Write reset [2024-11-13 19:20:30] debug: zh:ezsp:uart: --> [1ac038bc7e] [2024-11-13 19:20:30] debug: zh:ezsp:uart: -?- waiting reset [2024-11-13 19:20:30] debug: zh:ezsp:uart: <-- Error c20251a8bd7e [2024-11-13 19:20:30] debug: zh:ezsp:uart: Uart reseting [2024-11-13 19:20:30] debug: zh:ezsp:uart: --> Write reset [2024-11-13 19:20:30] debug: zh:ezsp:uart: --> [1ac038bc7e] [2024-11-13 19:20:30] debug: zh:ezsp:uart: -?- waiting reset [2024-11-13 19:20:30] debug: zh:ezsp:uart: <-- Error c20251a8bd7e [2024-11-13 19:20:30] debug: zh:ezsp:uart: Uart reseting [2024-11-13 19:20:30] debug: zh:ezsp:uart: --> Write reset [2024-11-13 19:20:30] debug: zh:ezsp:uart: --> [1ac038bc7e] [2024-11-13 19:20:30] debug: zh:ezsp:uart: -?- waiting reset [2024-11-13 19:20:31] debug: zh:ezsp:uart: <-- [c1020b0a527e] [2024-11-13 19:20:31] debug: zh:ezsp:uart: <-- RSTACK c1020b0a527e [2024-11-13 19:20:31] debug: zh:ezsp:uart: RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e [2024-11-13 19:20:31] debug: zh:ezsp:uart: <-- RSTACK c1020b0a527e [2024-11-13 19:20:31] debug: zh:ezsp:uart: RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e [2024-11-13 19:20:31] debug: zh:ezsp:uart: <-- RSTACK c1020b0a527e [2024-11-13 19:20:31] debug: zh:ezsp:uart: RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e [2024-11-13 19:20:31] debug: zh:ezsp:uart: -+- waiting reset success [2024-11-13 19:20:31] debug: zh:ezsp:uart: -+- waiting reset success [2024-11-13 19:20:31] debug: zh:ezsp:uart: -+- waiting reset success [2024-11-13 19:20:34] error: zh:ezsp:uart: --> Error: Error: {"sequence":4} after 4000ms [2024-11-13 19:20:34] error: zh:ezsp:uart: -!- break waiting (4) [2024-11-13 19:20:34] error: zh:ezsp:uart: Can't send DATA frame (3,2,0): 0b00010500 [2024-11-13 19:20:34] debug: zh:ezsp:uart: ->> DATA (3,2,1): 0b00010500 [2024-11-13 19:20:34] debug: zh:ezsp:uart: --> [3a4921a9512ac4db7e] [2024-11-13 19:20:34] debug: zh:ezsp:uart: -?- rewaiting (4) [2024-11-13 19:20:34] debug: zh:ezsp:ezsp: Time to watchdog ... 0 [2024-11-13 19:20:34] debug: zh:ezsp:ezsp: ==> nop: undefined [2024-11-13 19:20:38] error: zh:ezsp:uart: --> Error: Error: {"sequence":4} after 4000ms [2024-11-13 19:20:38] error: zh:ezsp:uart: -!- break rewaiting (4) [2024-11-13 19:20:38] error: zh:ezsp:uart: Can't resend DATA frame (3,2,1): 0b00010500 [2024-11-13 19:20:38] debug: zh:ezsp:ezsp: onSerialReset() [2024-11-13 19:20:38] debug: zh:ezsp:driv: onEzspReset() [2024-11-13 19:20:38] debug: zh:ezsp:driv: Reset connection. [2024-11-13 19:20:38] debug: zh:ezsp:driv: Stopping driver [2024-11-13 19:20:38] debug: zh:ezsp:ezsp: Closing Ezsp [2024-11-13 19:20:38] debug: zh:ezsp:uart: Closing UART [2024-11-13 19:20:38] error: zh:ezsp:ezsp: Watchdog heartbeat timeout Error: Failure send nop:{"type":"Buffer","data":[11,0,1,5,0]} [2024-11-13 19:20:38] debug: zh:ezsp:uart: Port closed. Error? null [2024-11-13 19:20:38] debug: zh:ezsp:ezsp: onSerialClose() [2024-11-13 19:20:39] debug: zh:ezsp:driv: Startup again. [2024-11-13 19:20:39] debug: zh:ezsp:uart: RTS/CTS config is off, enabling software flow control. [2024-11-13 19:20:39] debug: zh:ezsp:uart: Opening SerialPort with {"path":"/dev/serial/by-id/usb-Itead_Sonoff_Zigbee_3.0_USB_Dongle_Plus_V2_f45097c0c312ef118bf96db8bf9df066-if00-port0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true} [2024-11-13 19:20:39] debug: zh:ezsp:uart: Serialport opened [2024-11-13 19:20:39] debug: zh:ezsp:uart: Uart reseting [2024-11-13 19:20:39] debug: zh:ezsp:uart: --> Write reset [2024-11-13 19:20:39] debug: zh:ezsp:uart: --> [1ac038bc7e] [2024-11-13 19:20:39] debug: zh:ezsp:uart: -?- waiting reset [2024-11-13 19:20:40] debug: zh:ezsp:uart: <-- [c1020b0a527e] [2024-11-13 19:20:40] debug: zh:ezsp:uart: <-- RSTACK c1020b0a527e [2024-11-13 19:20:40] debug: zh:ezsp:uart: RSTACK Version: 2 Reason: RESET_SOFTWARE frame: c1020b0a527e [2024-11-13 19:20:40] debug: zh:ezsp:uart: -+- waiting reset success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> version: {"desiredProtocolVersion":4} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"version","_id_":0,"_isRequest_":true,"desiredProtocolVersion":4} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (0,0,0): 00000004 [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [004221a850ed2c7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (1) [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- [0142a1a8592855c6a6c87e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- DATA (0,1,0): 0142a1a8592855c6a6c87e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> ACK (1) [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [8160597e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- ACK (1): 0142a1a8592855c6a6c87e [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== Frame: 0080000d024074 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== 0x0: {"_cls_":"version","_id_":0,"_isRequest_":false,"protocolVersion":13,"stackType":2,"stackVersion":29760} [2024-11-13 19:20:42] debug: zh:ezsp:uart: -+- waiting (1) success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: Switching to eszp version 13 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> version: {"desiredProtocolVersion":13} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"version","_id_":0,"_isRequest_":true,"desiredProtocolVersion":13} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (1,1,0): 01000100000d [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [7d314321a9542a7d3899da7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (2) [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- [1243a1a9542a7d38b019e0ea307e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- DATA (1,2,0): 1243a1a9542a18b019e0ea307e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> ACK (2) [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [82503a7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- ACK (2): 1243a1a9542a18b019e0ea307e [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== Frame: 01800100000d024074 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== 0x0: {"_cls_":"version","_id_":0,"_isRequest_":false,"protocolVersion":13,"stackType":2,"stackVersion":29760} [2024-11-13 19:20:42] debug: zh:ezsp:uart: -+- waiting (2) success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_TC_REJOINS_USING_WELL_KNOWN_KEY_TIMEOUT_S = 90 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":56,"value":90} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":56,"value":90} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (2,2,0): 0200015300385a00 [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [224021a9072a2de8595e057e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (3) [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- [2340a1a9072a159ab77e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- DATA (2,3,0): 2340a1a9072a159ab77e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> ACK (3) [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [83401b7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- ACK (3): 2340a1a9072a159ab77e [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== Frame: 028001530000 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:42] debug: zh:ezsp:uart: -+- waiting (3) success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_TRUST_CENTER_ADDRESS_CACHE_SIZE = 2 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":25,"value":2} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":25,"value":2} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (3,3,0): 0300015300190200 [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [334121a9072a0cb05997eb7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (4) [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- [3441a1a9072a15f1287e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- DATA (3,4,0): 3441a1a9072a15f1287e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> ACK (4) [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [8430fc7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- ACK (4): 3441a1a9072a15f1287e [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== Frame: 038001530000 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:42] debug: zh:ezsp:uart: -+- waiting (4) success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_FRAGMENT_DELAY_MS = 50 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":29,"value":50} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":29,"value":50} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (4,4,0): 04000153001d3200 [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [444621a9072a08805993d67e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (5) [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- [4546a1a9072a1505697e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- DATA (4,5,0): 4546a1a9072a1505697e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> ACK (5) [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [8520dd7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- ACK (5): 4546a1a9072a1505697e [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== Frame: 048001530000 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:42] debug: zh:ezsp:uart: -+- waiting (5) success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_PAN_ID_CONFLICT_REPORT_THRESHOLD = 2 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":34,"value":2} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":34,"value":2} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (5,5,0): 0500015300220200 [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [554721a9072a37b05980d97e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (6) [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- [5647a1a9072a15af307e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- DATA (5,6,0): 5647a1a9072a15af307e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> ACK (6) [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [8610be7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- ACK (6): 5647a1a9072a15af307e [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== Frame: 058001530000 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:42] debug: zh:ezsp:uart: -+- waiting (6) success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_APPLICATION_ZDO_FLAGS = 3 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":42,"value":3} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":42,"value":3} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (6,6,0): 06000153002a0300 [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [664421a9072a3fb1590b7a7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (7) [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- [6744a1a9072a15803c7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- DATA (6,7,0): 6744a1a9072a15803c7e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> ACK (7) [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [87009f7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- ACK (7): 6744a1a9072a15803c7e [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== Frame: 068001530000 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:42] debug: zh:ezsp:uart: -+- waiting (7) success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_INDIRECT_TRANSMISSION_TIMEOUT = 7680 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":18,"value":7680} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":18,"value":7680} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (7,7,0): 070001530012001e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [774521a9072a07b2473edc7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (0) [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- [7045a1a9072a15eba37e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- DATA (7,0,0): 7045a1a9072a15eba37e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> ACK (0) [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [8070787e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- ACK (0): 7045a1a9072a15eba37e [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== Frame: 078001530000 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:42] debug: zh:ezsp:uart: -+- waiting (0) success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_END_DEVICE_POLL_TIMEOUT = 14 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":19,"value":14} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":19,"value":14} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (0,0,0): 0800015300130e00 [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [004a21a9072a06bc597d3aae7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (1) [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- [014aa1a9072a1512a07e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- DATA (0,1,0): 014aa1a9072a1512a07e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> ACK (1) [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [8160597e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- ACK (1): 014aa1a9072a1512a07e [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== Frame: 088001530000 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:42] debug: zh:ezsp:uart: -+- waiting (1) success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_SECURITY_LEVEL = 5 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":13,"value":5} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":13,"value":5} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (1,1,0): 09000153000d0500 [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [7d314b21a9072a7d38b75961387e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (2) [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- [124ba1a9072a15b8f97e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- DATA (1,2,0): 124ba1a9072a15b8f97e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> ACK (2) [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [82503a7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- ACK (2): 124ba1a9072a15b8f97e [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== Frame: 098001530000 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:42] debug: zh:ezsp:uart: -+- waiting (2) success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_STACK_PROFILE = 2 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":12,"value":2} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":12,"value":2} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (2,2,0): 0a000153000c0200 [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [224821a9072a19b059deac7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (3) [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- [2348a1a9072a1597f57e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- DATA (2,3,0): 2348a1a9072a1597f57e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> ACK (3) [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [83401b7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- ACK (3): 2348a1a9072a1597f57e [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== Frame: 0a8001530000 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:42] debug: zh:ezsp:uart: -+- waiting (3) success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: Set EzspConfigId.CONFIG_FRAGMENT_WINDOW_SIZE = 1 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> setConfigurationValue: {"configId":28,"value":1} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":true,"configId":28,"value":1} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (3,3,0): 0b000153001c0100 [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [334921a9072a09b35937927e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (4) [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- [3449a1a9072a15fc6a7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- DATA (3,4,0): 3449a1a9072a15fc6a7e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> ACK (4) [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [8430fc7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- ACK (4): 3449a1a9072a15fc6a7e [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== Frame: 0b8001530000 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== 0x53: {"_cls_":"setConfigurationValue","_id_":83,"_isRequest_":false,"status":0} [2024-11-13 19:20:42] debug: zh:ezsp:uart: -+- waiting (4) success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: Set EzspPolicyId.APP_KEY_REQUEST_POLICY = 96 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> setPolicy: {"policyId":6,"decisionId":96} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"setPolicy","_id_":85,"_isRequest_":true,"policyId":6,"decisionId":96} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (4,4,0): 0c00015500066000 [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [444e21a9012a7d33d2599bc67e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (5) [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- [454ea1a9012a15ba8b7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- DATA (4,5,0): 454ea1a9012a15ba8b7e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> ACK (5) [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [8520dd7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- ACK (5): 454ea1a9012a15ba8b7e [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== Frame: 0c8001550000 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== 0x55: {"_cls_":"setPolicy","_id_":85,"_isRequest_":false,"status":0} [2024-11-13 19:20:42] debug: zh:ezsp:uart: -+- waiting (5) success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: Set EzspPolicyId.TC_KEY_REQUEST_POLICY = 81 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> setPolicy: {"policyId":5,"decisionId":81} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"setPolicy","_id_":85,"_isRequest_":true,"policyId":5,"decisionId":81} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (5,5,0): 0d00015500055100 [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [554f21a9012a10e3590b3c7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (6) [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- [564fa1a9012a1510d27e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- DATA (5,6,0): 564fa1a9012a1510d27e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> ACK (6) [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [8610be7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- ACK (6): 564fa1a9012a1510d27e [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== Frame: 0d8001550000 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== 0x55: {"_cls_":"setPolicy","_id_":85,"_isRequest_":false,"status":0} [2024-11-13 19:20:42] debug: zh:ezsp:uart: -+- waiting (6) success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: Set EzspPolicyId.TRUST_CENTER_POLICY = 3 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> setPolicy: {"policyId":0,"decisionId":3} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"setPolicy","_id_":85,"_isRequest_":true,"policyId":0,"decisionId":3} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (6,6,0): 0e00015500000300 [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [664c21a9012a15b15999227e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (7) [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- [674ca1a9012a153fde7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- DATA (6,7,0): 674ca1a9012a153fde7e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> ACK (7) [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [87009f7e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- ACK (7): 674ca1a9012a153fde7e [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== Frame: 0e8001550000 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== 0x55: {"_cls_":"setPolicy","_id_":85,"_isRequest_":false,"status":0} [2024-11-13 19:20:42] debug: zh:ezsp:uart: -+- waiting (7) success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: Set EzspValueId.VALUE_END_DEVICE_KEEP_ALIVE_SUPPORT_MODE = 3 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> setValue: {"valueId":63,"value":3} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"setValue","_id_":171,"_isRequest_":true,"valueId":63,"value":3} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (7,7,0): 0f0001ab003f0003 [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [774d21a9ff2a2ab25a7d3a767e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (0) [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- [704da1a9ff2a15ac127e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- DATA (7,0,0): 704da1a9ff2a15ac127e [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> ACK (0) [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [8070787e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: <-- ACK (0): 704da1a9ff2a15ac127e [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== Frame: 0f8001ab0000 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: <== 0xab: {"_cls_":"setValue","_id_":171,"_isRequest_":false,"status":0} [2024-11-13 19:20:42] debug: zh:ezsp:uart: -+- waiting (0) success [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: Set EzspValueId.VALUE_CCA_THRESHOLD = 0 [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> setValue: {"valueId":21,"value":0} [2024-11-13 19:20:42] debug: zh:ezsp:ezsp: ==> {"_cls_":"setValue","_id_":171,"_isRequest_":true,"valueId":21,"value":0} [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> DATA (0,0,0): 100001ab00150000 [2024-11-13 19:20:42] debug: zh:ezsp:uart: --> [005221a9ff2a00b25995147e] [2024-11-13 19:20:42] debug: zh:ezsp:uart: -?- waiting (1) [2024-11-13 19:20:44] debug: zh:ezsp:uart: <-- [0952a1a9ff2a15dc387e] [2024-11-13 19:20:44] debug: zh:ezsp:uart: <-- DATA (0,1,1): 0952a1a9ff2a15dc387e [2024-11-13 19:20:44] debug: zh:ezsp:uart: --> ACK (1) [2024-11-13 19:20:44] debug: zh:ezsp:uart: --> [8160597e] [2024-11-13 19:20:44] debug: zh:ezsp:uart: <-- ACK (1): 0952a1a9ff2a15dc387e [2024-11-13 19:20:44] debug: zh:ezsp:ezsp: <== Frame: 108001ab0000 [2024-11-13 19:20:44] debug: zh:ezsp:ezsp: <== 0xab: {"_cls_":"setValue","_id_":171,"_isRequest_":false,"status":0} [2024-11-13 19:20:44] debug: zh:ezsp:uart: -+- waiting (1) success [2024-11-13 19:20:44] debug: zh:ezsp:ezsp: ==> setConcentrator: {"on":true,"concentratorType":65529,"minTime":10,"maxTime":90,"routeErrorThreshold":4,"deliveryFailureThreshold":3,"maxHops":0} [2024-11-13 19:20:44] debug: zh:ezsp:ezsp: ==> {"_cls_":"setConcentrator","_id_":16,"_isRequest_":true,"on":true,"concentratorType":65529,"minTime":10,"maxTime":90,"routeErrorThreshold":4,"deliveryFailureThreshold":3,"maxHops":0} [2024-11-13 19:20:44] debug: zh:ezsp:uart: --> DATA (1,1,0): 110001100001f9ff0a005a00040300 [2024-11-13 19:20:44] debug: zh:ezsp:uart: --> [7d315321a9442a144ba69e4a7faa519149699e7e] [2024-11-13 19:20:44] debug: zh:ezsp:uart: -?- waiting (2) [2024-11-13 19:20:44] debug: zh:ezsp:uart: <-- [1253a1a9442a15ebc27e] [2024-11-13 19:20:44] debug: zh:ezsp:uart: <-- DATA (1,2,0): 1253a1a9442a15ebc27e [2024-11-13 19:20:44] debug: zh:ezsp:uart: --> ACK (2) [2024-11-13 19:20:44] debug: zh:ezsp:uart: --> [82503a7e] [2024-11-13 19:20:44] debug: zh:ezsp:uart: <-- ACK (2): 1253a1a9442a15ebc27e [2024-11-13 19:20:44] debug: zh:ezsp:ezsp: <== Frame: 118001100000 [2024-11-13 19:20:44] debug: zh:ezsp:ezsp: <== 0x10: {"_cls_":"setConcentrator","_id_":16,"_isRequest_":false,"status":0} [2024-11-13 19:20:44] debug: zh:ezsp:uart: -+- waiting (2) success [2024-11-13 19:20:44] debug: zh:ezsp:ezsp: Set concentrator type: {"_cls_":"setConcentrator","_id_":16,"_isRequest_":false,"status":0} [2024-11-13 19:20:44] debug: zh:ezsp:ezsp: ==> setSourceRouteDiscoveryMode: {"mode":1} [2024-11-13 19:20:44] debug: zh:ezsp:ezsp: ==> {"_cls_":"setSourceRouteDiscoveryMode","_id_":90,"_isRequest_":true,"mode":1} [2024-11-13 19:20:44] debug: zh:ezsp:uart: --> DATA (2,2,0): 1200015a0001 [2024-11-13 19:20:44] debug: zh:ezsp:uart: --> [225021a90e2a1494327e] [2024-11-13 19:20:44] debug: zh:ezsp:uart: -?- waiting (3) [2024-11-13 19:20:44] debug: zh:ezsp:uart: <-- [2350a1a90e2a3db2599476767e] [2024-11-13 19:20:44] debug: zh:ezsp:uart: <-- DATA (2,3,0): 2350a1a90e2a3db2599476767e [2024-11-13 19:20:44] debug: zh:ezsp:uart: --> ACK (3) [2024-11-13 19:20:44] debug: zh:ezsp:uart: --> [83401b7e] [2024-11-13 19:20:44] debug: zh:ezsp:uart: <-- ACK (3): 2350a1a90e2a3db2599476767e [2024-11-13 19:20:44] debug: zh:ezsp:ezsp: <== Frame: 1280015a0028000000 [2024-11-13 19:20:44] debug: zh:ezsp:ezsp: <== 0x5a: {"_cls_":"setSourceRouteDiscoveryMode","_id_":90,"_isRequest_":false,"remainingTime":40} [2024-11-13 19:20:44] debug: zh:ezsp:uart: -+- waiting (3) success [2024-11-13 19:20:44] debug: zh:ezsp:ezsp: ==> addEndpoint: {"endpoint":1,"profileId":260,"deviceId":48879,"appFlags":0,"inputClusterCount":7,"outputClusterCount":20,"inputClusterList":[0,3,6,10,25,26,768],"outputClusterList":[0,3,4,5,6,8,32,768,1024,1026,1029,1030,1280,2817,2819,2820,1794,4096,64513,64514]} [2024-11-13 19:20:44] debug: zh:ezsp:ezsp: ==> {"_cls_":"addEndpoint","_id_":2,"_isRequest_":true,"endpoint":1,"profileId":260,"deviceId":48879,"appFlags":0,"inputClusterCount":7,"outputClusterCount":20,"inputClusterList":[0,3,6,10,25,26,768],"outputClusterList":[0,3,4,5,6,8,32,768,1024,1026,1029,1030,1280,2817,2819,2820,1794,4096,64513,64514]} [2024-11-13 19:20:44] debug: zh:ezsp:uart: --> DATA (3,3,0): 1300010200010401efbe0007140000030006000a0019001a0000030000030004000500060008002000000300040204050406040005010b030b040b0207001001fc02fc [2024-11-13 19:20:44] debug: zh:ezsp:uart: --> [335121a9562a14b6587bf425ad4192499f4e21abe7ce7d5e8be7c6638afc7d5e3ca7efcddb6f89ffcfdbf5d2698f4627abe8733fa3ee758740934f2d17bae277380c0ffbb91990397e] [2024-11-13 19:20:44] debug: zh:ezsp:uart: -?- waiting (4) [2024-11-13 19:20:45] debug: zh:ezsp:uart: <-- [3c51a1a9562a157d31ff7e] [2024-11-13 19:20:45] debug: zh:ezsp:uart: <-- DATA (3,4,1): 3c51a1a9562a1511ff7e [2024-11-13 19:20:45] debug: zh:ezsp:uart: --> ACK (4) [2024-11-13 19:20:45] debug: zh:ezsp:uart: --> [8430fc7e] [2024-11-13 19:20:45] debug: zh:ezsp:uart: <-- ACK (4): 3c51a1a9562a1511ff7e [2024-11-13 19:20:45] debug: zh:ezsp:ezsp: <== Frame: 138001020000 [2024-11-13 19:20:45] debug: zh:ezsp:ezsp: <== 0x2: {"_cls_":"addEndpoint","_id_":2,"_isRequest_":false,"status":0} [2024-11-13 19:20:45] debug: zh:ezsp:uart: -+- waiting (4) success [2024-11-13 19:20:45] debug: zh:ezsp:driv: Ezsp adding endpoint: {"_cls_":"addEndpoint","_id_":2,"_isRequest_":false,"status":0} [2024-11-13 19:20:45] debug: zh:ezsp:ezsp: ==> addEndpoint: {"endpoint":242,"profileId":41440,"deviceId":97,"appFlags":0,"inputClusterCount":0,"outputClusterCount":1,"inputClusterList":[],"outputClusterList":[33]} [2024-11-13 19:20:45] debug: zh:ezsp:ezsp: ==> {"_cls_":"addEndpoint","_id_":2,"_isRequest_":true,"endpoint":242,"profileId":41440,"deviceId":97,"appFlags":0,"inputClusterCount":0,"outputClusterCount":1,"inputClusterList":[],"outputClusterList":[33]} [2024-11-13 19:20:45] debug: zh:ezsp:uart: --> DATA (4,4,0): 1400010200f2e0a161000000012100 [2024-11-13 19:20:45] debug: zh:ezsp:uart: --> [445621a9562ae752f8f54a25aa54b349844e7e] [2024-11-13 19:20:45] debug: zh:ezsp:uart: -?- waiting (5) [2024-11-13 19:20:49] error: zh:ezsp:uart: --> Error: Error: {"sequence":5} after 4000ms [2024-11-13 19:20:49] error: zh:ezsp:uart: -!- break waiting (5) [2024-11-13 19:20:49] error: zh:ezsp:uart: Can't send DATA frame (4,4,0): 1400010200f2e0a161000000012100 [2024-11-13 19:20:49] debug: zh:ezsp:uart: ->> DATA (4,4,1): 1400010200f2e0a161000000012100 [2024-11-13 19:20:49] debug: zh:ezsp:uart: --> [4c5621a9562ae752f8f54a25aa54b34995cb7e] [2024-11-13 19:20:49] debug: zh:ezsp:uart: -?- rewaiting (5) [2024-11-13 19:20:49] debug: zh:ezsp:uart: <-- [8520dd7e] [2024-11-13 19:20:49] debug: zh:ezsp:uart: <-- ACK (5): 8520dd7e [2024-11-13 19:20:49] debug: zh:ezsp:uart: -+- rewaiting (5) success [2024-11-13 19:20:52] debug: zh:ezsp:ezsp: Time to watchdog ... 0 [2024-11-13 19:20:52] debug: zh:ezsp:ezsp: ==> nop: undefined [2024-11-13 19:20:59] debug: zh:ezsp:ezsp: ==> {"_cls_":"nop","_id_":5,"_isRequest_":true} [2024-11-13 19:20:59] debug: zh:ezsp:uart: --> DATA (5,4,0): 1500010500 [2024-11-13 19:20:59] debug: zh:ezsp:uart: --> [545721a9512ad0927e] [2024-11-13 19:20:59] debug: zh:ezsp:uart: -?- waiting (6) [2024-11-13 19:20:59] debug: zh:ezsp:driv: Reset error Error: Failure send addEndpoint:{"type":"Buffer","data":[20,0,1,2,0,242,224,161,97,0,0,0,1,33,0]} [2024-11-13 19:20:59] debug: zh:ezsp:driv: Stopping driver [2024-11-13 19:20:59] debug: zh:ezsp:ezsp: Closing Ezsp [2024-11-13 19:20:59] debug: zh:ezsp:uart: Closing UART [2024-11-13 19:20:59] debug: zh:ezsp:uart: Port closed. Error? null [2024-11-13 19:20:59] debug: zh:ezsp:ezsp: onSerialClose() [2024-11-13 19:20:59] debug: zh:ezsp:driv: onEzspClose() [2024-11-13 19:20:59] debug: zh:ezsp: onDriverClose() [2024-11-13 19:20:59] debug: zh:ezsp:ezsp: onSerialClose() [2024-11-13 19:20:59] debug: zh:ezsp:driv: onEzspClose() [2024-11-13 19:20:59] debug: zh:ezsp: onDriverClose() [2024-11-13 19:21:03] error: zh:ezsp:uart: --> Error: Error: {"sequence":6} after 4000ms [2024-11-13 19:21:03] error: zh:ezsp:uart: -!- break waiting (6) [2024-11-13 19:21:03] error: zh:ezsp:uart: Can't send DATA frame (5,4,0): 1500010500 [2024-11-13 19:21:04] debug: zh:ezsp:uart: ->> DATA (5,4,1): 1500010500 [2024-11-13 19:21:04] debug: zh:ezsp:uart: --> [5c5721a9512addd07e] [2024-11-13 19:21:04] debug: zh:ezsp:uart: -?- rewaiting (6) [2024-11-13 19:21:08] error: zh:ezsp:uart: --> Error: Error: {"sequence":6} after 4000ms [2024-11-13 19:21:08] error: zh:ezsp:uart: -!- break rewaiting (6) [2024-11-13 19:21:08] error: zh:ezsp:uart: Can't resend DATA frame (5,4,1): 1500010500 [2024-11-13 19:21:08] error: zh:ezsp:ezsp: Watchdog heartbeat timeout Error: Failure send nop:{"type":"Buffer","data":[21,0,1,5,0]} ```
Rainking80 commented 7 hours ago

That zlib error with ember-zli likely means you are using an older NodeJS version (it requires >=20.15.0).

Make sure to always use Software flow control, rtscts: false with Dongle-E, it does not support hardware flow control. I saw you set it as true in ember-zli screenshot.

That looping of ASH Adapter reset usually means one of the following:

  • The path is not right
  • The baudrate is not right

Basically, it can't communicate to the adapter properly (or at all).

After flashing the NVM3, did you re-flash one of the firmware files I linked before? Can you try running with log_level: debug in your configuration.yaml so I can get some more details? You can find me on Discord, DM me after joining zigbee2mqtt server, if you prefer sharing the logs that way.

advanced:
  log_level: debug

thanks i will set rtscts to false and re-test

Nerivec commented 7 hours ago

I think something is wrong with your configuration. That debug log is using ezsp not ember which doesn't match the config you posted before. Check that there isn't a sync problem between the configuration in the Z2M add-on page, and the yaml file itself.

Though since both drivers and ember-zli appear to be acting the same (adapter not responding most of the time), I'm going to guess that the "end problem" is something about the adapter or the hardware it is plugged into. Make sure to eliminate the usual, power cable/supply, USB cable. If you get a chance, grab the logs from dmesg, to see what the system sees.

Rainking80 commented 6 hours ago

I think something is wrong with your configuration. That debug log is using ezsp not ember which doesn't match the config you posted before. Check that there isn't a sync problem between the configuration in the Z2M add-on page, and the yaml file itself.

Though since both drivers and ember-zli appear to be acting the same (adapter not responding most of the time), I'm going to guess that the "end problem" is something about the adapter or the hardware it is plugged into. Make sure to eliminate the usual, power cable/supply, USB cable. If you get a chance, grab the logs from dmesg, to see what the system sees.

sorry, i tried both. i read that some people had stability issues with ember

here is the ember log: ``` [20:28:17] INFO: Preparing to start... [20:28:18] INFO: Socat not enabled [20:28:18] INFO: Starting Zigbee2MQTT... Starting Zigbee2MQTT without watchdog. [2024-11-13 20:28:20] info: z2m: Logging to console, file (filename: log.log) [2024-11-13 20:28:20] debug: z2m: Loaded state from file /config/zigbee2mqtt/state.json [2024-11-13 20:28:20] info: z2m: Starting Zigbee2MQTT version 1.41.0 (commit #unknown) [2024-11-13 20:28:20] debug: z2m: sd-notify loaded [2024-11-13 20:28:20] info: z2m: Starting zigbee-herdsman (2.1.7) [2024-11-13 20:28:20] debug: z2m: Using zigbee-herdsman with settings: '"{\"network\":{\"panID\":1321,\"extendedPanID\":[23,58,119,75,209,77,211,4],\"channelList\":[25],\"networkKey\":\"HIDDEN\"},\"databasePath\":\"/config/zigbee2mqtt/database.db\",\"databaseBackupPath\":\"/config/zigbee2mqtt/database.db.backup\",\"backupPath\":\"/config/zigbee2mqtt/coordinator_backup.json\",\"serialPort\":{\"baudRate\":115200,\"rtscts\":false,\"path\":\"/dev/serial/by-id/usb-Itead_Sonoff_Zigbee_3.0_USB_Dongle_Plus_V2_f45097c0c312ef118bf96db8bf9df066-if00-port0\",\"adapter\":\"ember\"},\"adapter\":{\"disableLED\":false}}"' [2024-11-13 20:28:20] info: zh:ember: Using default stack config. [2024-11-13 20:28:20] debug: zh:controller: Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":"HIDDEN","panID":1321,"extendedPanID":[23,58,119,75,209,77,211,4],"channelList":[25]},"serialPort":{"baudRate":115200,"rtscts":false,"path":"/dev/serial/by-id/usb-Itead_Sonoff_Zigbee_3.0_USB_Dongle_Plus_V2_f45097c0c312ef118bf96db8bf9df066-if00-port0","adapter":"ember"},"adapter":{"disableLED":false},"databasePath":"/config/zigbee2mqtt/database.db","databaseBackupPath":"/config/zigbee2mqtt/database.db.backup","backupPath":"/config/zigbee2mqtt/coordinator_backup.json"}' [2024-11-13 20:28:20] info: zh:ember: ======== Ember Adapter Starting ======== [2024-11-13 20:28:20] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-11-13 20:28:20] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-11-13 20:28:20] info: zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control. [2024-11-13 20:28:20] debug: zh:ember:uart:ash: Opening serial port with {"path":"/dev/serial/by-id/usb-Itead_Sonoff_Zigbee_3.0_USB_Dongle_Plus_V2_f45097c0c312ef118bf96db8bf9df066-if00-port0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true} [2024-11-13 20:28:20] info: zh:ember:uart:ash: Serial port opened [2024-11-13 20:28:20] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-11-13 20:28:20] debug: zh:ember:uart:ash: ---> [FRAME type=RST] [2024-11-13 20:28:20] debug: zh:ember:uart:ash: Waiting for RSTACK... 0/2500 [2024-11-13 20:28:20] debug: zh:ember:uart:ash: Waiting for RSTACK... 100/2500 [2024-11-13 20:28:20] debug: zh:ember:uart:ash: Waiting for RSTACK... 200/2500 [2024-11-13 20:28:20] debug: zh:ember:uart:ash: Waiting for RSTACK... 300/2500 [2024-11-13 20:28:20] debug: zh:ember:uart:ash: Waiting for RSTACK... 400/2500 [2024-11-13 20:28:20] debug: zh:ember:uart:ash: Waiting for RSTACK... 500/2500 [2024-11-13 20:28:21] debug: zh:ember:uart:ash: Waiting for RSTACK... 600/2500 [2024-11-13 20:28:21] debug: zh:ember:uart:ash: Waiting for RSTACK... 700/2500 [2024-11-13 20:28:21] debug: zh:ember:uart:ash: Waiting for RSTACK... 800/2500 [2024-11-13 20:28:21] debug: zh:ember:uart:ash: Waiting for RSTACK... 900/2500 [2024-11-13 20:28:21] debug: zh:ember:uart:ash: Waiting for RSTACK... 1000/2500 [2024-11-13 20:28:21] debug: zh:ember:uart:ash: Waiting for RSTACK... 1100/2500 [2024-11-13 20:28:21] debug: zh:ember:uart:ash: Waiting for RSTACK... 1200/2500 [2024-11-13 20:28:21] debug: zh:ember:uart:ash: Waiting for RSTACK... 1300/2500 [2024-11-13 20:28:21] debug: zh:ember:uart:ash: Waiting for RSTACK... 1400/2500 [2024-11-13 20:28:21] debug: zh:ember:uart:ash: Waiting for RSTACK... 1500/2500 [2024-11-13 20:28:22] debug: zh:ember:uart:ash: Waiting for RSTACK... 1600/2500 [2024-11-13 20:28:22] debug: zh:ember:uart:ash: Waiting for RSTACK... 1700/2500 [2024-11-13 20:28:22] debug: zh:ember:uart:ash: Waiting for RSTACK... 1800/2500 [2024-11-13 20:28:22] debug: zh:ember:uart:ash: Waiting for RSTACK... 1900/2500 [2024-11-13 20:28:22] debug: zh:ember:uart:ash: Waiting for RSTACK... 2000/2500 [2024-11-13 20:28:22] debug: zh:ember:uart:ash: Waiting for RSTACK... 2100/2500 [2024-11-13 20:28:22] debug: zh:ember:uart:ash: Waiting for RSTACK... 2200/2500 [2024-11-13 20:28:22] debug: zh:ember:uart:ash: Waiting for RSTACK... 2300/2500 [2024-11-13 20:28:22] debug: zh:ember:uart:ash: Waiting for RSTACK... 2400/2500 [2024-11-13 20:28:22] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-11-13 20:28:22] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-11-13 20:28:22] debug: zh:ember:uart:ash: ---> [FRAME type=RST] [2024-11-13 20:28:22] debug: zh:ember:uart:ash: Waiting for RSTACK... 0/2500 [2024-11-13 20:28:23] debug: zh:ember:uart:ash: Waiting for RSTACK... 100/2500 [2024-11-13 20:28:23] debug: zh:ember:uart:ash: Waiting for RSTACK... 200/2500 [2024-11-13 20:28:23] debug: zh:ember:uart:ash: Waiting for RSTACK... 300/2500 [2024-11-13 20:28:23] debug: zh:ember:uart:ash: Waiting for RSTACK... 400/2500 [2024-11-13 20:28:23] debug: zh:ember:uart:ash: Waiting for RSTACK... 500/2500 [2024-11-13 20:28:23] debug: zh:ember:uart:ash: Waiting for RSTACK... 600/2500 [2024-11-13 20:28:23] debug: zh:ember:uart:ash: Waiting for RSTACK... 700/2500 [2024-11-13 20:28:23] debug: zh:ember:uart:ash: Waiting for RSTACK... 800/2500 [2024-11-13 20:28:23] debug: zh:ember:uart:ash: Waiting for RSTACK... 900/2500 [2024-11-13 20:28:23] debug: zh:ember:uart:ash: Waiting for RSTACK... 1000/2500 [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=RSTACK] [2024-11-13 20:28:24] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0](ackRx=0) [2024-11-13 20:28:24] info: zh:ember:uart:ash: ======== ASH started ======== [2024-11-13 20:28:24] info: zh:ember:ezsp: ======== EZSP started ======== [2024-11-13 20:28:24] debug: zh:ember:ezsp: ===> [FRAME: ID=0:"VERSION" Seq=0 Len=4] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0](ackRx=0) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=0 frmTx=1) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0](frmRx=0) Added to rxQueue [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1](ackRx=1) [2024-11-13 20:28:24] debug: zh:ember:ezsp: <=== [FRAME: ID=0:"VERSION" Seq=0 Len=7] [2024-11-13 20:28:24] debug: zh:ember:ezsp: ===> [FRAME: ID=0:"VERSION" Seq=1 Len=6] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1](ackRx=1) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=1 frmTx=2) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1](frmRx=1) Added to rxQueue [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2](ackRx=2) [2024-11-13 20:28:24] debug: zh:ember:ezsp: <=== [FRAME: ID=0:"VERSION" Seq=1 Len=9] [2024-11-13 20:28:24] info: zh:ember: Adapter EZSP protocol version (13) lower than Host. Switched. [2024-11-13 20:28:24] debug: zh:ember: Adapter info: EZSPVersion=13 StackType=2 StackVersion=29760 [2024-11-13 20:28:24] debug: zh:ember:ezsp: ===> [FRAME: ID=170:"GET_VALUE" Seq=2 Len=6] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2](ackRx=2) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3](ackRx=2 frmTx=3) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2](frmRx=2) Added to rxQueue [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3](ackRx=3) [2024-11-13 20:28:24] debug: zh:ember:ezsp: <=== [FRAME: ID=170:"GET_VALUE" Seq=2 Len=14] [2024-11-13 20:28:24] info: zh:ember: Adapter version info: {"ezsp":13,"revision":"7.4.4 [GA]","build":0,"major":7,"minor":4,"patch":4,"special":0,"type":170} [2024-11-13 20:28:24] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=3 Len=8] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3](ackRx=3) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4](ackRx=3 frmTx=4) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3](frmRx=3) Added to rxQueue [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4](ackRx=4) [2024-11-13 20:28:24] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=3 Len=6] [2024-11-13 20:28:24] debug: zh:ember: [EzspConfigId] SET 'TRUST_CENTER_ADDRESS_CACHE_SIZE' TO '2' with status=OK. [2024-11-13 20:28:24] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=4 Len=8] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4](ackRx=4) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5](ackRx=4 frmTx=5) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4](frmRx=4) Added to rxQueue [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5](ackRx=5) [2024-11-13 20:28:24] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=4 Len=6] [2024-11-13 20:28:24] debug: zh:ember: [EzspConfigId] SET 'INDIRECT_TRANSMISSION_TIMEOUT' TO '7680' with status=OK. [2024-11-13 20:28:24] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=5 Len=8] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5](ackRx=5) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6](ackRx=5 frmTx=6) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5](frmRx=5) Added to rxQueue [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6](ackRx=6) [2024-11-13 20:28:24] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=5 Len=6] [2024-11-13 20:28:24] debug: zh:ember: [EzspConfigId] SET 'MAX_HOPS' TO '30' with status=OK. [2024-11-13 20:28:24] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=6 Len=8] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6](ackRx=6) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7](ackRx=6 frmTx=7) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6](frmRx=6) Added to rxQueue [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7](ackRx=7) [2024-11-13 20:28:24] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=6 Len=6] [2024-11-13 20:28:24] debug: zh:ember: [EzspConfigId] SET 'SUPPORTED_NETWORKS' TO '1' with status=OK. [2024-11-13 20:28:24] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=7 Len=7] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7](ackRx=7) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0](ackRx=7 frmTx=0) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7](frmRx=7) Added to rxQueue [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0](ackRx=0) [2024-11-13 20:28:24] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=7 Len=6] [2024-11-13 20:28:24] debug: zh:ember: [EzspPolicyId] SET 'BINDING_MODIFICATION_POLICY' TO '18' with status=OK. [2024-11-13 20:28:24] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=8 Len=7] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0](ackRx=0) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=0 frmTx=1) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0](frmRx=0) Added to rxQueue [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1](ackRx=1) [2024-11-13 20:28:24] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=8 Len=6] [2024-11-13 20:28:24] debug: zh:ember: [EzspPolicyId] SET 'MESSAGE_CONTENTS_IN_CALLBACK_POLICY' TO '64' with status=OK. [2024-11-13 20:28:24] debug: zh:ember:ezsp: ===> [FRAME: ID=171:"SET_VALUE" Seq=9 Len=9] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1](ackRx=1) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=1 frmTx=2) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1](frmRx=1) Added to rxQueue [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2](ackRx=2) [2024-11-13 20:28:24] debug: zh:ember:ezsp: <=== [FRAME: ID=171:"SET_VALUE" Seq=9 Len=6] [2024-11-13 20:28:24] debug: zh:ember: [EzspValueId] SET 'TRANSIENT_DEVICE_TIMEOUT' TO '16,39' with status=OK. [2024-11-13 20:28:24] debug: zh:ember:ezsp: ===> [FRAME: ID=21:"SET_MANUFACTURER_CODE" Seq=10 Len=7] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2](ackRx=2) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3](ackRx=2 frmTx=3) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2](frmRx=2) Added to rxQueue [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3](ackRx=3) [2024-11-13 20:28:24] debug: zh:ember:ezsp: <=== [FRAME: ID=21:"SET_MANUFACTURER_CODE" Seq=10 Len=5] [2024-11-13 20:28:24] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=11 Len=8] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3](ackRx=3) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4](ackRx=3 frmTx=4) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3](frmRx=3) Added to rxQueue [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4](ackRx=4) [2024-11-13 20:28:24] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=11 Len=6] [2024-11-13 20:28:24] debug: zh:ember: [EzspConfigId] SET 'STACK_PROFILE' TO '2' with status=OK. [2024-11-13 20:28:24] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=12 Len=8] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4](ackRx=4) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5](ackRx=4 frmTx=5) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4](frmRx=4) Added to rxQueue [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5](ackRx=5) [2024-11-13 20:28:24] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=12 Len=6] [2024-11-13 20:28:24] debug: zh:ember: [EzspConfigId] SET 'SECURITY_LEVEL' TO '5' with status=OK. [2024-11-13 20:28:24] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=13 Len=8] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5](ackRx=5) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6](ackRx=5 frmTx=6) [2024-11-13 20:28:24] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5](frmRx=5) Added to rxQueue [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6](ackRx=6) [2024-11-13 20:28:24] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=13 Len=6] [2024-11-13 20:28:24] debug: zh:ember: [EzspConfigId] SET 'MAX_END_DEVICE_CHILDREN' TO '32' with status=OK. [2024-11-13 20:28:24] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=14 Len=8] [2024-11-13 20:28:24] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6](ackRx=6) [2024-11-13 20:28:38] debug: zh:ember:ezsp: =x=> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=14 Len=8] Error: ASH_ERROR_TIMEOUTS [2024-11-13 20:28:38] error: zh:ember:ezsp: ERROR Transaction failure; status=ASH_ERROR_TIMEOUTS. Last Frame: [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=13 Len=6]. [2024-11-13 20:28:38] error: zh:ember: Adapter fatal error: ASH_ERROR_TIMEOUTS [2024-11-13 20:28:38] error: z2m: Error while starting zigbee-herdsman [2024-11-13 20:28:38] error: z2m: Failed to start zigbee [2024-11-13 20:28:38] error: z2m: Check https://www.zigbee2mqtt.io/guide/installation/20_zigbee2mqtt-fails-to-start.html for possible solutions [2024-11-13 20:28:38] error: z2m: Exiting... [2024-11-13 20:28:38] error: z2m: Error: ASH_ERROR_TIMEOUTS at Ezsp.ezspSetConfigurationValue (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:1466:19) at EmberAdapter.emberSetEzspConfigValue (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1463:24) at EmberAdapter.initEzsp (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:711:9) at EmberAdapter.start (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:1598:24) at Controller.start (/app/node_modules/zigbee-herdsman/src/controller/controller.ts:137:29) at Zigbee.start (/app/lib/zigbee.ts:69:27) at Controller.start (/app/lib/controller.ts:161:27) ```
Rainking80 commented 6 hours ago

as a note (could be related): i installed a full backup from my pi4 to my p5. first i had issues to find the usb devices, so i had to change the group permissions for the usb port to dialout.

image

Rainking80 commented 6 hours ago

this is what i see with dmesg: ( the port 16 messages at the end of the log pop up when zigbee runs into that error)

[12909.104050] kauditd_printk_skb: 42 callbacks suppressed
[12909.104054] audit: type=1334 audit(1731527637.884:1326): prog-id=268 op=UNLOAD
[12909.142294] audit: type=1325 audit(1731527637.920:1327): table=nat:318 family=2 entries=1 op=nft_unregister_rule pid=363811 subj=unconfined comm="iptables"
[12909.142463] audit: type=1300 audit(1731527637.920:1327): arch=c00000b7 syscall=211 success=yes exit=512 a0=3 a1=7fead204b8 a2=0 a3=1 items=0 ppid=643 pid=363811 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-nft-multi" subj=unconfined key=(null)
[12909.142471] audit: type=1327 audit(1731527637.920:1327): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D74006E6174002D4400444F434B4552002D7000746370002D6400302F30002D2D64706F72740038343835002D6A00444E4154002D2D746F2D64657374696E6174696F6E003137322E33302E33332E31303A383438350000002D690068617373696F
[12909.145484] audit: type=1325 audit(1731527637.924:1328): table=nat:319 family=2 entries=1 op=nft_unregister_rule pid=363813 subj=unconfined comm="iptables"
[12909.145490] audit: type=1300 audit(1731527637.924:1328): arch=c00000b7 syscall=211 success=yes exit=604 a0=3 a1=7fd270ebb8 a2=0 a3=1 items=0 ppid=643 pid=363813 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-nft-multi" subj=unconfined key=(null)
[12909.145495] audit: type=1327 audit(1731527637.924:1328): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D74006E6174002D4400504F5354524F5554494E47002D7000746370002D73003137322E33302E33332E3130002D64003137322E33302E33332E3130002D2D64706F72740038343835002D6A004D415351554552414445
[12909.179281] audit: type=1325 audit(1731527637.956:1329): table=filter:320 family=2 entries=1 op=nft_unregister_rule pid=363815 subj=unconfined comm="iptables"
[12909.179291] audit: type=1300 audit(1731527637.956:1329): arch=c00000b7 syscall=211 success=yes exit=652 a0=3 a1=7fde48f148 a2=0 a3=1 items=0 ppid=643 pid=363815 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0 fsgid=0 tty=(none) ses=4294967295 comm="iptables" exe="/usr/sbin/xtables-nft-multi" subj=unconfined key=(null)
[12909.179296] audit: type=1327 audit(1731527637.956:1329): proctitle=2F7573722F7362696E2F69707461626C6573002D2D77616974002D740066696C746572002D4400444F434B45520000002D690068617373696F002D6F0068617373696F002D7000746370002D64003137322E33302E33332E3130002D2D64706F72740038343835002D6A00414343455054
[12909.210479] vethc7268ac: renamed from eth0
[12909.231781] hassio: port 16(vetheee67ec) entered disabled state
[12909.257090] hassio: port 16(vetheee67ec) entered disabled state
[12909.258246] vetheee67ec (unregistering): left allmulticast mode
[12909.258254] vetheee67ec (unregistering): left promiscuous mode
[12909.258266] hassio: port 16(vetheee67ec) entered disabled state
[12909.451103] hassio: port 16(veth49ad628) entered blocking state
[12909.451111] hassio: port 16(veth49ad628) entered disabled state
[12909.451128] veth49ad628: entered allmulticast mode
[12909.451249] veth49ad628: entered promiscuous mode
[12909.451403] hassio: port 16(veth49ad628) entered blocking state
[12909.451408] hassio: port 16(veth49ad628) entered forwarding state
[12909.660079] eth0: renamed from veth784acad