zigbee2mqtt
zigbee2mqtt copied to clipboard
Published
20 hours ago •
Koenkk
Koenkk
Periodic disconnection of the adapter "ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT."
What happened?
The Zigbee Sonoff Dongle E adapter periodically disconnects and then reconnects. The error occurs with both old and new ember firmware versions. I changed the USB port. The 2.4 GHz Wi-Fi at home is set to channel 1, and the Zigbee adapter is on channel 11. Zigbee2MQTT is running on a mini PC (x64), and the power supply is stable.
What did you expect to happen?
No response
How to reproduce it (minimal and precise)
Sudden disconnection at random times, then the device reconnects and everything works normally.
Zigbee2MQTT version
1.40.0
Adapter firmware version
EmberZNet 7.4.3 [GA]
Adapter
Sonoff ZBDongle-E
Setup
Docker x64 ubuntu server
Debug log
[2024-09-04 21:03:52] error: z2m: Failed to read state of 'Switch Zal' after reconnect (ZCL command 0xa*****/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":10563,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":45},"zclSequence":197,"commandIdentifier":1} timed out after 10000ms))
[2024-09-04 21:04:32] error: z2m: Failed to read state of 'Switch San' after reconnect (ZCL command 0xa*****/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":24703,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":50},"zclSequence":199,"commandIdentifier":1} timed out after 10000ms))
[2024-09-04 21:04:39] error: z2m: Failed to read state of 'Switch VAn' after reconnect (ZCL command 0xa*****/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":52757,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":56},"zclSequence":200,"commandIdentifier":1} timed out after 10000ms))
[2024-09-04 21:06:54] error: z2m: Failed to read state of 'Switch Kuh' after reconnect (ZCL command 0xa*****/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":61550,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":121},"zclSequence":212,"commandIdentifier":1} timed out after 10000ms))
[2024-09-05 13:08:28] error: z2m: Failed to read state of 'Switch Kuh' after reconnect (ZCL command 0xa*****/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":61550,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":90},"zclSequence":65,"commandIdentifier":1} timed out after 10000ms))
[2024-09-05 13:08:43] error: zh:ember:uart:ash: Received ERROR from adapter, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-09-05 13:08:43] error: zh:ember:uart:ash: ASH disconnected | Adapter status: ASH_NCP_FATAL_ERROR
[2024-09-05 13:08:43] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-09-05 13:08:43] error: zh:ember: Adapter fatal error: HOST_FATAL_ERROR
[2024-09-05 13:08:51] error: zh:ember:ezsp: ERROR Transaction failure; status=ASH_ERROR_TIMEOUTS. Last Frame: [FRAME: ID=52:"SEND_UNICAST" Seq=174 Len=7].
[2024-09-05 13:09:13] error: z2m: Adapter disconnected, stopping
I'm also facing a similar issue with an SMLight SLZB-06M running latest firmware (20240510) connected to my HA by the USB/Serial connection.
I already have the rtscts: false in the config.
This is the log when it crashes:
[2024-09-08 15:10:43] error: zh:ember:uart:ash: Received ERROR from adapter, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-09-08 15:10:43] error: zh:ember:uart:ash: ASH disconnected | Adapter status: ASH_NCP_FATAL_ERROR
[2024-09-08 15:10:43] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-09-08 15:10:43] error: zh:ember: Adapter fatal error: HOST_FATAL_ERROR
[2024-09-08 15:10:43] info: zh:ember:uart:ash: ASH COUNTERS since last clear:
[2024-09-08 15:10:43] info: zh:ember:uart:ash: Total frames: RX=624, TX=776
[2024-09-08 15:10:43] info: zh:ember:uart:ash: Cancelled : RX=0, TX=0
[2024-09-08 15:10:43] info: zh:ember:uart:ash: DATA frames : RX=613, TX=156
[2024-09-08 15:10:43] info: zh:ember:uart:ash: DATA bytes : RX=14408, TX=4015
[2024-09-08 15:10:43] info: zh:ember:uart:ash: Retry frames: RX=9, TX=3
[2024-09-08 15:10:43] info: zh:ember:uart:ash: ACK frames : RX=0, TX=616
[2024-09-08 15:10:43] info: zh:ember:uart:ash: NAK frames : RX=0, TX=0
[2024-09-08 15:10:43] info: zh:ember:uart:ash: nRdy frames : RX=0, TX=0
[2024-09-08 15:10:43] info: zh:ember:uart:ash: CRC errors : RX=0
[2024-09-08 15:10:43] info: zh:ember:uart:ash: Comm errors : RX=0
[2024-09-08 15:10:43] info: zh:ember:uart:ash: Length < minimum: RX=0
[2024-09-08 15:10:43] info: zh:ember:uart:ash: Length > maximum: RX=0
[2024-09-08 15:10:43] info: zh:ember:uart:ash: Bad controls : RX=0
[2024-09-08 15:10:43] info: zh:ember:uart:ash: Bad lengths : RX=0
[2024-09-08 15:10:43] info: zh:ember:uart:ash: Bad ACK numbers : RX=0
[2024-09-08 15:10:43] info: zh:ember:uart:ash: Out of buffers : RX=0
[2024-09-08 15:10:43] info: zh:ember:uart:ash: Retry dupes : RX=9
[2024-09-08 15:10:43] info: zh:ember:uart:ash: Out of sequence : RX=0
[2024-09-08 15:10:43] info: zh:ember:uart:ash: ACK timeouts : RX=3
[2024-09-08 15:10:51] error: zh:ember:ezsp: ERROR Transaction failure; status=ASH_ERROR_TIMEOUTS. Last Frame: [FRAME: ID=52:"SEND_UNICAST" Seq=154 Len=7].
[2024-09-08 15:10:51] error: zh:ember:ezsp: ERROR Transaction failure; status=ASH_NCP_FATAL_ERROR. Last Frame: [FRAME: ID=52:"SEND_UNICAST" Seq=154 Len=7].
[2024-09-08 15:10:51] error: z2m: Publish 'set' 'state' to 'Luz de Teste' failed: 'Error: ZCL command 0x980c33fffea32f91/1 genLevelCtrl.moveToLevelWithOnOff({"level":241,"transtime":0}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"reservedBits":0,"writeUndiv":false}) failed (~x~> [ZCL to=40307] Failed to send request with status=FAIL.)'
[2024-09-08 15:11:13] info: zh:ember:uart:ash: Port closed.
[2024-09-08 15:11:13] info: zh:ember:uart:ash: ======== ASH stopped ========
[2024-09-08 15:11:13] info: zh:ember:ezsp: ======== EZSP stopped ========
[2024-09-08 15:11:13] info: zh:ember: ======== Ember Adapter Stopped ========
[2024-09-08 15:11:13] error: z2m: Adapter disconnected, stopping
[2024-09-08 15:11:13] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload '{"state":"offline"}'
[2024-09-08 15:11:13] info: z2m: Disconnecting from MQTT server
[2024-09-08 15:11:13] info: z2m: Stopping zigbee-herdsman...
[2024-09-08 15:11:13] info: z2m: Stopped zigbee-herdsman
[2024-09-08 15:11:13] info: z2m: Stopped Zigbee2MQTT
And this is the boot following the crash:
[2024-09-08 15:11:18] info: z2m: Logging to console, file (filename: log.log)
[2024-09-08 15:11:18] info: z2m: Starting Zigbee2MQTT version 1.40.1 (commit #unknown)
[2024-09-08 15:11:18] info: z2m: Starting zigbee-herdsman (0.57.3)
[2024-09-08 15:11:18] info: zh:ember: Using default stack config.
[2024-09-08 15:11:18] info: zh:ember: ======== Ember Adapter Starting ========
[2024-09-08 15:11:18] info: zh:ember:ezsp: ======== EZSP starting ========
[2024-09-08 15:11:18] info: zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-09-08 15:11:18] info: zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control.
[2024-09-08 15:11:18] info: zh:ember:uart:ash: Serial port opened
[2024-09-08 15:11:18] info: zh:ember:uart:ash: ======== ASH starting ========
[2024-09-08 15:11:19] info: zh:ember:uart:ash: ======== ASH connected ========
[2024-09-08 15:11:19] info: zh:ember:uart:ash: ======== ASH started ========
[2024-09-08 15:11:19] info: zh:ember:ezsp: ======== EZSP started ========
[2024-09-08 15:11:19] info: zh:ember: Adapter EZSP protocol version (13) lower than Host. Switched.
[2024-09-08 15:11:19] 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-09-08 15:11:20] info: zh:ember: [STACK STATUS] Network up.
[2024-09-08 15:11:20] info: zh:ember: [INIT TC] Adapter network matches config.
[2024-09-08 15:11:20] info: zh:ember: [CONCENTRATOR] Started source route discovery. 1248ms until next broadcast.
[2024-09-08 15:11:20] info: z2m: zigbee-herdsman started (resumed)
[2024-09-08 15:11:20] info: z2m: Coordinator firmware version: '{"meta":{"build":0,"ezsp":13,"major":7,"minor":4,"patch":1,"revision":"7.4.1 [GA]","special":0,"type":170},"type":"EmberZNet"}'
I noticed that my adapter didn’t disconnect for 4 days, everything was fine, but now the errors started appearing again. I noticed that the errors are coming from switches without a neutral line, and it happens on all of them. After these errors, the adapter stops and restarts.
[2024-09-09 21:43:37] error: z2m: Failed to read state of 'vikl kor' after reconnect (ZCL command 0xa4c1**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":26079,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":143},"zclSequence":3,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:44:01] error: z2m: Failed to read state of 'vikl kuh' after reconnect (ZCL command 0xa4c1384**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":61550,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":151},"zclSequence":7,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:44:06] error: z2m: Failed to read state of 'vikl kor' after reconnect (ZCL command 0xa4c1**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":26079,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":157},"zclSequence":10,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:44:13] error: z2m: Failed to read state of 'vikl vann' after reconnect (ZCL command 0xa4c138**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":52757,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":163},"zclSequence":11,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:44:24] error: z2m: Failed to read state of 'vikl kor' after reconnect (ZCL command 0xa4c1**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":26079,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":165},"zclSequence":13,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:45:00] error: z2m: Failed to read state of 'vikl zal' after reconnect (ZCL command 0xa4c138**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":10563,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":184},"zclSequence":16,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:45:18] error: z2m: Failed to read state of 'vikl kor' after reconnect (ZCL command 0xa4c1**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":26079,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":199},"zclSequence":18,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:47:04] error: z2m: Publish 'set' 'state' to 'vikl san' failed: 'Error: ZCL command 0xa4c*********/2 genOnOff.off({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":24703,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":2,"options":4416,"groupId":0,"sequence":2},"zclSequence":37,"commandIdentifier":11} timed out after 10000ms)'
[2024-09-09 21:48:11] error: z2m: Failed to read state of 'vikl zal' after reconnect (ZCL command 0xa4c138**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":10563,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":39},"zclSequence":48,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:48:41] error: z2m: Failed to read state of 'vikl kor' after reconnect (ZCL command 0xa4c1**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":26079,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":53},"zclSequence":51,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:48:46] error: z2m: Failed to read state of 'vikl kuh' after reconnect (ZCL command 0xa4c1384**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":61550,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":54},"zclSequence":52,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:49:11] error: z2m: Failed to read state of 'vikl zal' after reconnect (ZCL command 0xa4c138**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":10563,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":59},"zclSequence":55,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:49:13] error: z2m: Failed to read state of 'vikl kuh' after reconnect (ZCL command 0xa4c1384**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":61550,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":61},"zclSequence":57,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:49:17] error: z2m: Failed to read state of 'vikl kor' after reconnect (ZCL command 0xa4c1**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":26079,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":65},"zclSequence":58,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:49:17] error: z2m: Failed to read state of 'vikl vann' after reconnect (ZCL command 0xa4c138**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":52757,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":66},"zclSequence":60,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:49:25] error: z2m: Failed to read state of 'vikl kuh' after reconnect (ZCL command 0xa4c1384**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":61550,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":70},"zclSequence":61,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:49:34] error: z2m: Failed to read state of 'vikl vann' after reconnect (ZCL command 0xa4c138**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":52757,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":71},"zclSequence":62,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:49:36] error: z2m: Failed to read state of 'vikl kor' after reconnect (ZCL command 0xa4c1**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":26079,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":76},"zclSequence":63,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:49:36] error: z2m: Failed to read state of 'vikl zal' after reconnect (ZCL command 0xa4c138**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":10563,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":77},"zclSequence":64,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:50:08] error: z2m: Failed to read state of 'vikl vann' after reconnect (ZCL command 0xa4c138**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":52757,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":91},"zclSequence":69,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:50:14] error: z2m: Failed to read state of 'vikl kor' after reconnect (ZCL command 0xa4c1**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":26079,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":92},"zclSequence":70,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:50:30] error: z2m: Failed to read state of 'vikl kor' after reconnect (ZCL command 0xa4c1**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":26079,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":104},"zclSequence":71,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:50:41] error: zh:ember:uart:ash: Received ERROR from adapter, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-09-09 21:50:41] error: zh:ember:uart:ash: ASH disconnected | Adapter status: ASH_NCP_FATAL_ERROR
[2024-09-09 21:50:41] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-09-09 21:50:41] error: zh:ember: Adapter fatal error: HOST_FATAL_ERROR
[2024-09-09 21:50:43] error: z2m: Failed to read state of 'vikl kuh' after reconnect (ZCL command 0xa4c1384**********/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"reservedBits":0,"writeUndiv":false}) failed ({"target":61550,"apsFrame":{"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":115},"zclSequence":74,"commandIdentifier":1} timed out after 10000ms))
[2024-09-09 21:50:50] error: zh:ember:ezsp: ERROR Transaction failure; status=ASH_ERROR_TIMEOUTS. Last Frame: [FRAME: ID=52:"SEND_UNICAST" Seq=13 Len=7].
[2024-09-09 21:50:50] error: zh:ember:ezsp: ERROR Transaction failure; status=ASH_NCP_FATAL_ERROR. Last Frame: [FRAME: ID=52:"SEND_UNICAST" Seq=13 Len=7].
[2024-09-09 21:50:50] error: zh:controller:device: Read response to 0xa4c138********** failed (ZCL command 0xa4c138**********/1 genTime.readRsp({"localTime":779233836}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":1,"reservedBits":0,"transactionSequenceNumber":70,"writeUndiv":false}) failed (~x~> [ZCL to=10563] Failed to send request with status=FAIL.))
[2024-09-09 21:50:50] error: zh:controller:device: Read response to 0xa4c1********** failed (ZCL command 0xa4c1**********/1 genTime.readRsp({"localTime":779233836}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":1,"reservedBits":0,"transactionSequenceNumber":172,"writeUndiv":false}) failed (~x~> [ZCL to=26079] Failed to send request with status=FAIL.))
[2024-09-09 21:50:53] error: zh:controller:device: Read response to 0xa4c138********** failed (ZCL command 0xa4c138**********/1 genTime.readRsp({"localTime":779233836}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":1,"reservedBits":0,"transactionSequenceNumber":70,"writeUndiv":false}) failed (~x~> [ZCL to=10563] Failed to send request with status=NETWORK_DOWN.))
[2024-09-09 21:50:53] error: zh:controller:device: Read response to 0xa4c1********** failed (ZCL command 0xa4c1**********/1 genTime.readRsp({"localTime":779233836}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":1,"reservedBits":0,"transactionSequenceNumber":172,"writeUndiv":false}) failed (~x~> [ZCL to=26079] Failed to send request with status=NETWORK_DOWN.))
[2024-09-09 21:50:56] error: zh:controller:device: Read response to 0xa4c138********** failed (ZCL command 0xa4c138**********/1 genTime.readRsp({"localTime":779233837}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":1,"reservedBits":0,"transactionSequenceNumber":70,"writeUndiv":false}) failed (~x~> [ZCL to=10563] Failed to send request with status=NETWORK_DOWN.))
[2024-09-09 21:51:12] error: z2m: Adapter disconnected, stopping
I realized that, at least in my case, I can 100% reproduce the issue by triggering a device firmware update, specially for endpoint devices (I think they are slow to comm).
This is an attempt to update the firmware of a Philips Hue Motion Sensor. I had to start the update at least 5 times before completing it (luckily this sensor stores the partially "downloaded" firmware and the next attempt start where the previous has finished). By the way, I was testing a Hue Dimmer just before the reset.
And I also tried a few times to update 2 devices at the same time and it is impossible.
[2024-09-15 17:22:25] info: z2m: Update of '0x0017880106f763b6' at 2.33%, ≈ 47 minutes remaining
[2024-09-15 17:22:25] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/0x0017880106f763b6', payload '{"battery":100,"illuminance":null,"illuminance_lux":null,"led_indication":null,"linkquality":148,"motion_sensitivity":null,"occupancy":false,"occupancy_timeout":0,"temperature":null,"update":{"installed_version":1107315168,"latest_version":1107323831,"progress":2.33,"remaining":2843,"state":"updating"},"update_available":null}'
[2024-09-15 17:22:28] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Hue Dimmer1', payload '{"action":"on_press","action_duration":null,"battery":2,"linkquality":124,"update":{"installed_version":1107324829,"latest_version":1107324829,"state":"idle"},"update_available":null}'
[2024-09-15 17:22:28] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Hue Dimmer1', payload '{"action":"","action_duration":null,"battery":2,"linkquality":124,"update":{"installed_version":1107324829,"latest_version":1107324829,"state":"idle"},"update_available":null}'
[2024-09-15 17:22:28] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Hue Dimmer1/action', payload 'on_press'
[2024-09-15 17:22:28] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Hue Dimmer1', payload '{"action":"on_press_release","action_duration":null,"battery":2,"linkquality":124,"update":{"installed_version":1107324829,"latest_version":1107324829,"state":"idle"},"update_available":null}'
[2024-09-15 17:22:28] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Hue Dimmer1', payload '{"action":"","action_duration":null,"battery":2,"linkquality":124,"update":{"installed_version":1107324829,"latest_version":1107324829,"state":"idle"},"update_available":null}'
[2024-09-15 17:22:28] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Hue Dimmer1/action', payload 'on_press_release'
[2024-09-15 17:22:28] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Bedroom Light', payload '{"brightness":254,"color":{"x":0.4369,"y":0.4041},"color_mode":"color_temp","color_options":null,"color_temp":333,"linkquality":168,"power_on_behavior":null,"state":"ON","update":{"installed_version":268572245,"latest_version":268572245,"state":"idle"},"update_available":null}'
[2024-09-15 17:22:31] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Hue Dimmer1', payload '{"action":"off_press","action_duration":null,"battery":2,"linkquality":120,"update":{"installed_version":1107324829,"latest_version":1107324829,"state":"idle"},"update_available":null}'
[2024-09-15 17:22:31] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Hue Dimmer1', payload '{"action":"","action_duration":null,"battery":2,"linkquality":120,"update":{"installed_version":1107324829,"latest_version":1107324829,"state":"idle"},"update_available":null}'
[2024-09-15 17:22:31] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Hue Dimmer1/action', payload 'off_press'
[2024-09-15 17:22:31] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Hue Dimmer1', payload '{"action":"off_press_release","action_duration":null,"battery":2,"linkquality":120,"update":{"installed_version":1107324829,"latest_version":1107324829,"state":"idle"},"update_available":null}'
[2024-09-15 17:22:31] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Hue Dimmer1', payload '{"action":"","action_duration":null,"battery":2,"linkquality":120,"update":{"installed_version":1107324829,"latest_version":1107324829,"state":"idle"},"update_available":null}'
[2024-09-15 17:22:31] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Hue Dimmer1/action', payload 'off_press_release'
[2024-09-15 17:22:37] error: zh:ember:uart:ash: Received ERROR from adapter, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-09-15 17:22:37] error: zh:ember:uart:ash: ASH disconnected | Adapter status: ASH_NCP_FATAL_ERROR
[2024-09-15 17:22:37] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-09-15 17:22:37] error: zh:ember: Adapter fatal error: HOST_FATAL_ERROR
[2024-09-15 17:22:37] info: zh:ember:uart:ash: ASH COUNTERS since last clear:
[2024-09-15 17:22:37] info: zh:ember:uart:ash: Total frames: RX=1191, TX=1506
[2024-09-15 17:22:37] info: zh:ember:uart:ash: Cancelled : RX=0, TX=0
[2024-09-15 17:22:37] info: zh:ember:uart:ash: DATA frames : RX=1176, TX=342
[2024-09-15 17:22:37] info: zh:ember:uart:ash: DATA bytes : RX=25322, TX=16611
[2024-09-15 17:22:37] info: zh:ember:uart:ash: Retry frames: RX=13, TX=2
[2024-09-15 17:22:37] info: zh:ember:uart:ash: ACK frames : RX=0, TX=1161
[2024-09-15 17:22:37] info: zh:ember:uart:ash: NAK frames : RX=0, TX=0
[2024-09-15 17:22:37] info: zh:ember:uart:ash: nRdy frames : RX=0, TX=0
[2024-09-15 17:22:37] info: zh:ember:uart:ash: CRC errors : RX=0
[2024-09-15 17:22:37] info: zh:ember:uart:ash: Comm errors : RX=0
[2024-09-15 17:22:37] info: zh:ember:uart:ash: Length < minimum: RX=0
[2024-09-15 17:22:37] info: zh:ember:uart:ash: Length > maximum: RX=0
[2024-09-15 17:22:37] info: zh:ember:uart:ash: Bad controls : RX=0
[2024-09-15 17:22:37] info: zh:ember:uart:ash: Bad lengths : RX=0
[2024-09-15 17:22:37] info: zh:ember:uart:ash: Bad ACK numbers : RX=0
[2024-09-15 17:22:37] info: zh:ember:uart:ash: Out of buffers : RX=0
[2024-09-15 17:22:37] info: zh:ember:uart:ash: Retry dupes : RX=13
[2024-09-15 17:22:37] info: zh:ember:uart:ash: Out of sequence : RX=0
[2024-09-15 17:22:37] info: zh:ember:uart:ash: ACK timeouts : RX=2
[2024-09-15 17:22:45] error: zh:ember:ezsp: ERROR Transaction failure; status=ASH_ERROR_TIMEOUTS. Last Frame: [FRAME: ID=52:"SEND_UNICAST" Seq=84 Len=7].
[2024-09-15 17:22:45] error: zh:ember:ezsp: ERROR Transaction failure; status=ASH_NCP_FATAL_ERROR. Last Frame: [FRAME: ID=52:"SEND_UNICAST" Seq=84 Len=7].
[2024-09-15 17:22:45] error: z2m: Publish 'set' 'state' to 'Bedroom Light' failed: 'Error: ZCL command 0x1c34f1fffe5dcb50/1 genOnOff.off({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"reservedBits":0,"writeUndiv":false}) failed (~x~> [ZCL to=7962] Failed to send request with status=FAIL.)'
[2024-09-15 17:23:07] info: zh:ember:uart:ash: Port closed.
[2024-09-15 17:23:07] info: zh:ember:uart:ash: ======== ASH stopped ========
[2024-09-15 17:23:07] info: zh:ember:ezsp: ======== EZSP stopped ========
[2024-09-15 17:23:07] info: zh:ember: ======== Ember Adapter Stopped ========
[2024-09-15 17:23:07] error: z2m: Adapter disconnected, stopping
[2024-09-15 17:23:07] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload '{"state":"offline"}'
[2024-09-15 17:23:07] info: z2m: Disconnecting from MQTT server
[2024-09-15 17:23:07] info: z2m: Stopping zigbee-herdsman...
[2024-09-15 17:23:07] info: z2m: Stopped zigbee-herdsman
[2024-09-15 17:23:07] info: z2m: Stopped Zigbee2MQTT
I can reproduce this consistently. If I try to pair 2 RODRET at the same time it will crash 100% of the times.
It even crashes If I do 2 RODRET devices one after the other.
info 2024-09-20 18:16:08z2m: Zigbee: allowing new devices to join.
info 2024-09-20 18:16:08zh:ember: [STACK STATUS] Network opened.
info 2024-09-20 18:16:08z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/response/permit_join', payload '{"data":{"time":254,"value":true},"status":"ok","transaction":"o1f91-1"}'
info 2024-09-20 18:16:19zh:controller: Interview for '0xecf64cfffe35bb44' started
info 2024-09-20 18:16:19z2m: Starting interview of '0xecf64cfffe35bb44'
info 2024-09-20 18:16:19z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0xecf64cfffe35bb44","ieee_address":"0xecf64cfffe35bb44","status":"started"},"type":"device_interview"}'
info 2024-09-20 18:16:20z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0xecf64cfffe35bb44","ieee_address":"0xecf64cfffe35bb44"},"type":"device_announce"}'
info 2024-09-20 18:16:31zh:controller: Succesfully interviewed '0xecf64cfffe35bb44'
info 2024-09-20 18:16:31z2m: Successfully interviewed '0xecf64cfffe35bb44', device has successfully been paired
info 2024-09-20 18:16:31z2m: Device '0xecf64cfffe35bb44' is supported, identified as: IKEA RODRET wireless dimmer/power switch (E2201)
info 2024-09-20 18:16:32z2m: Configuring '0xecf64cfffe35bb44'
info 2024-09-20 18:16:32z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"definition":{"description":"RODRET wireless dimmer/power switch","exposes":[{"access":2,"category":"config","description":"Initiate device identification. This device is asleep by default.You may need to wake it up first before sending the identify command.","label":"Identify","name":"identify","property":"identify","type":"enum","values":["identify"]},{"access":5,"category":"diagnostic","description":"Remaining battery in %","label":"Battery","name":"battery","property":"battery","type":"numeric","unit":"%","value_max":100,"value_min":0},{"access":1,"category":"diagnostic","description":"Triggered action (e.g. a button click)","label":"Action","name":"action","property":"action","type":"enum","values":["on","off","brightness_move_up","brightness_move_down","brightness_stop"]},{"access":1,"category":"diagnostic","description":"Link quality (signal strength)","label":"Linkquality","name":"linkquality","property":"linkquality","type":"numeric","unit":"lqi","value_max":255,"value_min":0}],"model":"E2201","options":[{"access":2,"description":"Sets the duration of the identification procedure in seconds (i.e., how long the device would flash).The value ranges from 1 to 30 seconds (default: 3).","label":"Identify timeout","name":"identify_timeout","property":"identify_timeout","type":"numeric","value_max":30,"value_min":1},{"access":2,"description":"Simulate a brightness value. If this device provides a brightness_move_up or brightness_move_down action it is possible to specify the update interval and delta. The action_brightness_delta indicates the delta for each interval. ","features":[{"access":2,"description":"Delta per interval, 20 by default","label":"Delta","name":"delta","property":"delta","type":"numeric","value_min":0},{"access":2,"description":"Interval duration","label":"Interval","name":"interval","property":"interval","type":"numeric","unit":"ms","value_min":0}],"label":"Simulated brightness","name":"simulated_brightness","property":"simulated_brightness","type":"composite"}],"supports_ota":true,"vendor":"IKEA"},"friendly_name":"0xecf64cfffe35bb44","ieee_address":"0xecf64cfffe35bb44","status":"successful","supported":true},"type":"device_interview"}'
info 2024-09-20 18:16:37z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/0xecf64cfffe35bb44', payload '{"action":null,"battery":83,"linkquality":224,"update":{"installed_version":-1,"latest_version":-1,"state":null},"update_available":null}'
info 2024-09-20 18:16:37z2m: Successfully configured '0xecf64cfffe35bb44'
info 2024-09-20 18:17:00z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/0x8c6fb9fffec98a2a', payload '{"battery":86,"illuminance":6989,"illuminance_lux":5,"linkquality":204,"occupancy":false,"update":{"installed_version":16777303,"latest_version":16777316,"state":"available"},"update_available":null}'
info 2024-09-20 18:17:31z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/0xd44867fffe4fa6fe', payload '{"action":null,"battery":84,"linkquality":255,"update":{"installed_version":16777287,"latest_version":16777303,"state":"available"},"update_available":null}'
info 2024-09-20 18:17:31z2m: Update available for '0xd44867fffe4fa6fe'
info 2024-09-20 18:17:37z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/0xecf64cfffe35bb44', payload '{"action":"brightness_move_down","action_rate":83,"battery":83,"linkquality":224,"update":{"installed_version":-1,"latest_version":-1,"state":null},"update_available":null}'
info 2024-09-20 18:17:37z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/0xecf64cfffe35bb44', payload '{"action":"","battery":83,"linkquality":224,"update":{"installed_version":-1,"latest_version":-1,"state":null},"update_available":null}'
info 2024-09-20 18:17:37z2m:mqtt: MQTT publish: topic 'homeassistant/device_automation/0xecf64cfffe35bb44/action_brightness_move_down/config', payload '{"automation_type":"trigger","device":{"identifiers":["zigbee2mqtt_0xecf64cfffe35bb44"],"manufacturer":"IKEA","model":"RODRET wireless dimmer/power switch (E2201)","name":"0xecf64cfffe35bb44","sw_version":"1.0.47","via_device":"zigbee2mqtt_bridge_0x8c65a3fffe52309a"},"origin":{"name":"Zigbee2MQTT","sw":"1.40.1","url":"https://www.zigbee2mqtt.io"},"payload":"brightness_move_down","subtype":"brightness_move_down","topic":"zigbee2mqtt/0xecf64cfffe35bb44/action","type":"action"}'
info 2024-09-20 18:17:37z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/0xecf64cfffe35bb44/action', payload 'brightness_move_down'
info 2024-09-20 18:17:37z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/0xecf64cfffe35bb44', payload '{"action":"brightness_stop","battery":83,"linkquality":216,"update":{"installed_version":-1,"latest_version":-1,"state":null},"update_available":null}'
info 2024-09-20 18:17:37z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/0xecf64cfffe35bb44', payload '{"action":"","battery":83,"linkquality":216,"update":{"installed_version":-1,"latest_version":-1,"state":null},"update_available":null}'
info 2024-09-20 18:17:37z2m:mqtt: MQTT publish: topic 'homeassistant/device_automation/0xecf64cfffe35bb44/action_brightness_stop/config', payload '{"automation_type":"trigger","device":{"identifiers":["zigbee2mqtt_0xecf64cfffe35bb44"],"manufacturer":"IKEA","model":"RODRET wireless dimmer/power switch (E2201)","name":"0xecf64cfffe35bb44","sw_version":"1.0.47","via_device":"zigbee2mqtt_bridge_0x8c65a3fffe52309a"},"origin":{"name":"Zigbee2MQTT","sw":"1.40.1","url":"https://www.zigbee2mqtt.io"},"payload":"brightness_stop","subtype":"brightness_stop","topic":"zigbee2mqtt/0xecf64cfffe35bb44/action","type":"action"}'
info 2024-09-20 18:17:37z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/0xecf64cfffe35bb44/action', payload 'brightness_stop'
info 2024-09-20 18:17:42z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/0xd44867fffe16d61b/availability', payload '{"state":"online"}'
info 2024-09-20 18:17:42zh:controller: Interview for '0xd44867fffe16d61b' started
info 2024-09-20 18:17:42z2m: Device '0xd44867fffe16d61b' joined
info 2024-09-20 18:17:42z2m: Starting interview of '0xd44867fffe16d61b'
info 2024-09-20 18:17:43z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0xd44867fffe16d61b","ieee_address":"0xd44867fffe16d61b"},"type":"device_joined"}'
info 2024-09-20 18:17:43z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0xd44867fffe16d61b","ieee_address":"0xd44867fffe16d61b","status":"started"},"type":"device_interview"}'
info 2024-09-20 18:17:43z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/event', payload '{"data":{"friendly_name":"0xd44867fffe16d61b","ieee_address":"0xd44867fffe16d61b"},"type":"device_announce"}'
error 2024-09-20 18:17:53zh:ember:uart:ash: Received ERROR from adapter, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
error 2024-09-20 18:17:53zh:ember:uart:ash: ASH disconnected | Adapter status: ASH_NCP_FATAL_ERROR
error 2024-09-20 18:17:53zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
error 2024-09-20 18:17:53zh:ember: Adapter fatal error: HOST_FATAL_ERROR
info 2024-09-20 18:17:53zh:ember:uart:ash: ASH COUNTERS since last clear:
info 2024-09-20 18:17:53zh:ember:uart:ash: Total frames: RX=190, TX=263
info 2024-09-20 18:17:53zh:ember:uart:ash: Cancelled : RX=0, TX=0
info 2024-09-20 18:17:53zh:ember:uart:ash: DATA frames : RX=182, TX=75
info 2024-09-20 18:17:53zh:ember:uart:ash: DATA bytes : RX=3290, TX=1391
info 2024-09-20 18:17:53zh:ember:uart:ash: Retry frames: RX=6, TX=4
info 2024-09-20 18:17:53zh:ember:uart:ash: ACK frames : RX=0, TX=183
info 2024-09-20 18:17:53zh:ember:uart:ash: NAK frames : RX=0, TX=0
info 2024-09-20 18:17:53zh:ember:uart:ash: nRdy frames : RX=0, TX=0
info 2024-09-20 18:17:53zh:ember:uart:ash: CRC errors : RX=0
info 2024-09-20 18:17:53zh:ember:uart:ash: Comm errors : RX=0
info 2024-09-20 18:17:53zh:ember:uart:ash: Length < minimum: RX=0
info 2024-09-20 18:17:53zh:ember:uart:ash: Length > maximum: RX=0
info 2024-09-20 18:17:53zh:ember:uart:ash: Bad controls : RX=0
info 2024-09-20 18:17:53zh:ember:uart:ash: Bad lengths : RX=0
info 2024-09-20 18:17:53zh:ember:uart:ash: Bad ACK numbers : RX=0
info 2024-09-20 18:17:53zh:ember:uart:ash: Out of buffers : RX=0
info 2024-09-20 18:17:53zh:ember:uart:ash: Retry dupes : RX=6
info 2024-09-20 18:17:53zh:ember:uart:ash: Out of sequence : RX=0
info 2024-09-20 18:17:53zh:ember:uart:ash: ACK timeouts : RX=4
error 2024-09-20 18:18:01zh:ember:ezsp: ERROR Transaction failure; status=ASH_ERROR_TIMEOUTS. Last Frame: [FRAME: ID=52:"SEND_UNICAST" Seq=73 Len=7].
Could you try with the 8.0.1 firmware? https://github.com/Koenkk/zigbee2mqtt/discussions/23224#discussioncomment-10422347
I just did.
Flashing logs
~/Downloads/firmware-build-sonoff_zbdonglee_ncp-uart-sw_115200_8.0.1.0 took 1m1s
❯ ember-zli bootloader
[2024-09-21 00:50:26.712] info: cli: Data folder: /Users/skois/ember-zli.
? Path: /dev/tty.SLAB_USBtoUART, Baudrate: 115200, RTS/CTS: false. Use this config? no
? Adapter connection type Serial
? Adapter firmware baudrate 115200
? Serial port ITead undefined (/dev/tty.usbserial-10)
? Flow control Software Flow Control (rtscts=false)
? Adapter model Sonoff ZBDongle-E
[2024-09-21 00:50:26.560] info: gecko: Connecting to bootloader...
[2024-09-21 00:50:26.656] info: serial: Serial port opened
? Force reset into bootloader? no
[2024-09-21 00:50:26.226] info: serial: Closing serial connection...
[2024-09-21 00:50:26.293] info: serial: Transport closed.
[2024-09-21 00:50:26.295] info: gecko: Unable to enter bootloader.
? Is currently installed firmware RCP (multiprotocol)? no
[2024-09-21 00:50:26.947] info: zh:ember:ezsp: ======== EZSP starting ========
[2024-09-21 00:50:26.948] info: zh:ember:uart:ash: ======== ASH Adapter reset ========
[2024-09-21 00:50:26.949] info: zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control.
[2024-09-21 00:50:26.048] info: zh:ember:uart:ash: Serial port opened
[2024-09-21 00:50:26.050] info: zh:ember:uart:ash: ======== ASH starting ========
[2024-09-21 00:50:26.657] info: zh:ember:uart:ash: ======== ASH connected ========
[2024-09-21 00:50:26.675] info: zh:ember:uart:ash: ======== ASH started ========
[2024-09-21 00:50:26.676] info: zh:ember:ezsp: ======== EZSP started ========
[2024-09-21 00:50:26.694] info: ember: NCP version: {"ezsp":14,"revision":"8.0.1 [GA]","build":270,"major":8,"minor":0,"patch":1,"special":0,"type":170}
[2024-09-21 00:50:26.766] info: zh:ember:uart:ash: Port closed.
[2024-09-21 00:50:26.767] info: zh:ember:uart:ash: ======== ASH stopped ========
[2024-09-21 00:50:26.767] info: zh:ember:ezsp: ======== EZSP stopped ========
[2024-09-21 00:50:26.860] info: serial: Serial port opened
[2024-09-21 00:50:26.869] info: gecko: Connected to bootloader.
? Menu Get info
[2024-09-21 00:50:26.345] info: gecko: Gecko Bootloader v1.12.00.
? Menu Update firmware
? Firmware Source Select file in data folder (/Users/skois/ember-zli)
? Firmware file sonoff_zbdonglee_ncp-uart-sw_115200_8.0.1.0.gbl
[2024-09-21 00:50:26.999] info: gecko: Firmware file metadata: {"baudrate":115200,"ezsp_version":"8.0.1.0","fw_type":"ncp-uart-sw","metadata_version":1,"sdk_version":"2024.6.1"}
? Version: 8.0.1.0, Baudrate: 115200. Proceed with this firmware? yes
[2024-09-21 00:50:26.359] info: gecko: Firmware upload completed.
? Menu Exit bootloader
[2024-09-21 00:50:26.546] info: serial: Closing serial connection...
[2024-09-21 00:50:26.612] info: serial: Transport closed.
Z2M adapter log
[2024-09-21 00:53:53] info: zh:ember: Adapter version info: {"ezsp":14,"revision":"8.0.1 [GA]","build":270,"major":8,"minor":0,"patch":1,"special":0,"type":170}
Tried to switch 5 bulbs at the same time.
2024-09-21 00:53:19zh:ember:uart:ash: Received ERROR from adapter, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
error 2024-09-21 00:53:19zh:ember:uart:ash: ASH disconnected | Adapter status: ASH_NCP_FATAL_ERROR
error 2024-09-21 00:53:19zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
error 2024-09-21 00:53:19zh:ember: Adapter fatal error: HOST_FATAL_ERROR
info 2024-09-21 00:53:19zh:ember:uart:ash: ASH COUNTERS since last clear:
info 2024-09-21 00:53:19zh:ember:uart:ash: Total frames: RX=87, TX=128
info 2024-09-21 00:53:19zh:ember:uart:ash: Cancelled : RX=0, TX=0
info 2024-09-21 00:53:19zh:ember:uart:ash: DATA frames : RX=70, TX=47
info 2024-09-21 00:53:19zh:ember:uart:ash: DATA bytes : RX=1255, TX=639
info 2024-09-21 00:53:19zh:ember:uart:ash: Retry frames: RX=15, TX=3
info 2024-09-21 00:53:19zh:ember:uart:ash: ACK frames : RX=0, TX=77
info 2024-09-21 00:53:19zh:ember:uart:ash: NAK frames : RX=0, TX=0
info 2024-09-21 00:53:19zh:ember:uart:ash: nRdy frames : RX=0, TX=0
info 2024-09-21 00:53:19zh:ember:uart:ash: CRC errors : RX=0
info 2024-09-21 00:53:19zh:ember:uart:ash: Comm errors : RX=0
info 2024-09-21 00:53:19zh:ember:uart:ash: Length < minimum: RX=0
info 2024-09-21 00:53:19zh:ember:uart:ash: Length > maximum: RX=0
info 2024-09-21 00:53:19zh:ember:uart:ash: Bad controls : RX=0
info 2024-09-21 00:53:19zh:ember:uart:ash: Bad lengths : RX=0
info 2024-09-21 00:53:19zh:ember:uart:ash: Bad ACK numbers : RX=0
info 2024-09-21 00:53:19zh:ember:uart:ash: Out of buffers : RX=0
info 2024-09-21 00:53:19zh:ember:uart:ash: Retry dupes : RX=15
info 2024-09-21 00:53:19zh:ember:uart:ash: Out of sequence : RX=0
info 2024-09-21 00:53:19zh:ember:uart:ash: ACK timeouts : RX=3
@stavros-k I assume you didn't rename the file before flashing? If so, you didn't pick the "max" version as Koenkk intended. https://github.com/Nerivec/silabs-firmware-builder/actions/runs/10512841278/artifacts/1843552001 Can you try that one and report back?
Можете ли вы попробовать прошивку 8.0.1? #23224 (комментарий)
It seems that the errors I’m experiencing might still be due to the devices themselves, although it’s strange that the issue appears specifically with switches that don’t have a neutral line, and it happens with all of them at once.
After reconnecting the devices, I get the following message for all of them:
zh:ember: [ZDO] Device '10563' is only compliant with revision '21' of the ZigBee specification (current revision: 22).
This shouldn't affect the device reconnections or stop z2m, right?
@YoungRus Seems some networks are having troubles with message volume/rate. Try the firmware mentioned above, it increases the capabilities of the adapter, and so far has been able to fix that kind of issue.
No, that message is only to inform that the device is not really recent (the ZigBee version it uses is older). 21 shouldn't bring too many problems though.
@stavros-k I assume you didn't rename the file before flashing? If so, you didn't pick the "max" version as Koenkk intended. https://github.com/Nerivec/silabs-firmware-builder/actions/runs/10512841278/artifacts/1843552001 Can you try that one and report back?
Sorry I thought the goal was to use 8.x.x version.
Tried max and boy, oh boy! I could spam all lights at the same time on and off and had ZERO crashes.
I tried to "push" it a bit. 2 OTA updates running fine + tried to start a 3rd.
[2024-09-22 16:54:14] debug: zh:ember:ezsp: <=== [CBFRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=243 Len=54]
[2024-09-22 16:54:14] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":1,"destinationEndpoint":1,"options":64,"groupId":0,"sequence":247}], [packetInfo:{"senderShortId":37021,"senderLongId":"0x0000000000000000","bindingIndex":255,"addressIndex":255,"lastHopLqi":0,"lastHopRssi":0,"lastHopTimestamp":25}], [messageContents=015803007c11cd1157000001329600003f]
[2024-09-22 16:54:14] debug: zh:controller: Received payload: clusterID=25, address=37021, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=0, frame={"header":{"frameControl":{"frameType":1,"manufacturerSpecific":false,"direction":0,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":88,"commandIdentifier":3},"payload":{"fieldControl":0,"manufacturerCode":4476,"imageType":4557,"fileVersion":16777303,"fileOffset":38450,"maximumDataSize":63},"command":{"ID":3,"response":5,"parameters":[{"name":"fieldControl","type":32},{"name":"manufacturerCode","type":33},{"name":"imageType","type":33},{"name":"fileVersion","type":35},{"name":"fileOffset","type":35},{"name":"maximumDataSize","type":32}],"name":"imageBlockRequest"}}
[2024-09-22 16:54:14] debug: z2m: Received Zigbee message from 'Office Light Switch', type 'commandImageBlockRequest', cluster 'genOta', data '{"fieldControl":0,"fileOffset":38450,"fileVersion":16777303,"imageType":4557,"manufacturerCode":4476,"maximumDataSize":63}' from endpoint 1 with groupID 0
[2024-09-22 16:54:15] debug: zh:ember:uart:ash: <--- [FRAME type=ERROR]
[2024-09-22 16:54:15] error: zh:ember:uart:ash: Received ERROR from adapter, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-09-22 16:54:15] error: zh:ember:uart:ash: ASH disconnected | Adapter status: ASH_NCP_FATAL_ERROR
[2024-09-22 16:54:15] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-09-22 16:54:15] error: zh:ember: Adapter fatal error: HOST_FATAL_ERROR
[2024-09-22 16:54:15] debug: zh:controller: Adapter disconnected
[2024-09-22 16:54:15] info: zh:ember:uart:ash: ASH COUNTERS since last clear:
[2024-09-22 16:54:15] info: zh:ember:uart:ash: Total frames: RX=4831, TX=6272
[2024-09-22 16:54:15] info: zh:ember:uart:ash: Cancelled : RX=0, TX=0
[2024-09-22 16:54:15] info: zh:ember:uart:ash: DATA frames : RX=4826, TX=1525
[2024-09-22 16:54:15] info: zh:ember:uart:ash: DATA bytes : RX=139387, TX=116681
[2024-09-22 16:54:15] info: zh:ember:uart:ash: Retry frames: RX=3, TX=3
[2024-09-22 16:54:15] info: zh:ember:uart:ash: ACK frames : RX=0, TX=4743
[2024-09-22 16:54:15] info: zh:ember:uart:ash: NAK frames : RX=0, TX=0
[2024-09-22 16:54:15] info: zh:ember:uart:ash: nRdy frames : RX=0, TX=0
[2024-09-22 16:54:15] info: zh:ember:uart:ash: CRC errors : RX=0
[2024-09-22 16:54:15] info: zh:ember:uart:ash: Comm errors : RX=0
[2024-09-22 16:54:15] info: zh:ember:uart:ash: Length < minimum: RX=0
[2024-09-22 16:54:15] info: zh:ember:uart:ash: Length > maximum: RX=0
[2024-09-22 16:54:15] info: zh:ember:uart:ash: Bad controls : RX=0
[2024-09-22 16:54:15] info: zh:ember:uart:ash: Bad lengths : RX=0
[2024-09-22 16:54:15] info: zh:ember:uart:ash: Bad ACK numbers : RX=0
[2024-09-22 16:54:15] info: zh:ember:uart:ash: Out of buffers : RX=0
[2024-09-22 16:54:15] info: zh:ember:uart:ash: Retry dupes : RX=3
[2024-09-22 16:54:15] info: zh:ember:uart:ash: Out of sequence : RX=0
[2024-09-22 16:54:15] info: zh:ember:uart:ash: ACK timeouts : RX=3
Single OTA update still crashed it :(
[2024-09-22 17:30:12] debug: zhc:ota:common: Update at 30.13%, remaining 3818.489138566131 seconds
[2024-09-22 17:30:12] info: z2m: Update of 'Living Room Light Switch' at 30.13%, ≈ 64 minutes remaining
[2024-09-22 17:30:12] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Living Room Light Switch', payload '{"action":null,"battery":83,"linkquality":0,"update":{"installed_version":16777287,"latest_version":16777303,"progress":30.13,"remaining":3818,"state":"updating"},"update_available":null}'
[2024-09-22 17:30:12] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-09-22 17:30:12] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0](ackRx=0 frmTx=0)
[2024-09-22 17:30:12] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7](frmRx=7) Added to rxQueue
[2024-09-22 17:30:12] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0](ackRx=0)
[2024-09-22 17:30:12] debug: zh:ember:ezsp: <=== [CBFRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=7 Len=26]
[2024-09-22 17:30:12] debug: zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [status=OK], [type=DIRECT], [indexOrDestination=16413], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":1,"destinationEndpoint":1,"options":4352,"groupId":0,"sequence":190}], [messageTag=19]
[2024-09-22 17:30:13] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-09-22 17:30:13] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0](ackRx=0 frmTx=0)
[2024-09-22 17:30:13] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=0](frmRx=0) Added to rxQueue
[2024-09-22 17:30:13] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1](ackRx=0)
[2024-09-22 17:30:13] debug: zh:ember:ezsp: <=== [CBFRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=7 Len=54]
[2024-09-22 17:30:13] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":1,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":21}], [packetInfo:{"senderShortId":16413,"senderLongId":"0x0000000000000000","bindingIndex":255,"addressIndex":255,"lastHopLqi":0,"lastHopRssi":0,"lastHopTimestamp":25}], [messageContents=012703007c11cd1157000001363c01003f]
[2024-09-22 17:30:13] debug: zh:controller: Received payload: clusterID=25, address=16413, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=0, frame={"header":{"frameControl":{"frameType":1,"manufacturerSpecific":false,"direction":0,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":39,"commandIdentifier":3},"payload":{"fieldControl":0,"manufacturerCode":4476,"imageType":4557,"fileVersion":16777303,"fileOffset":80950,"maximumDataSize":63},"command":{"ID":3,"response":5,"parameters":[{"name":"fieldControl","type":32},{"name":"manufacturerCode","type":33},{"name":"imageType","type":33},{"name":"fileVersion","type":35},{"name":"fileOffset","type":35},{"name":"maximumDataSize","type":32}],"name":"imageBlockRequest"}}
[2024-09-22 17:30:13] debug: z2m: Received Zigbee message from 'Living Room Light Switch', type 'commandImageBlockRequest', cluster 'genOta', data '{"fieldControl":0,"fileOffset":80950,"fileVersion":16777303,"imageType":4557,"manufacturerCode":4476,"maximumDataSize":63}' from endpoint 1 with groupID 0
[2024-09-22 17:30:13] debug: zhc:ota:common: Request offsets: fileOffset=80950 pageOffset=0 maximumDataSize=63
[2024-09-22 17:30:13] debug: zhc:ota:common: Payload offsets: start=80950 end=81000 dataSize=50
[2024-09-22 17:30:13] debug: zh:controller:endpoint: CommandResponse 0xecf64cfffe35bb44/1 genOta.imageBlockResponse({"status":0,"manufacturerCode":4476,"imageType":4557,"fileVersion":16777303,"fileOffset":80950,"dataSize":50,"data":{"type":"Buffer","data":[6,72,244,247,85,249,8,155,16,43,3,208,187,33,3,72,244,247,78,249,18,176,112,189,0,68,64,4,16,40,4,0,48,181,13,70,0,33,145,176,4,70,36,34,7,168,6,145,33,240]}}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"reservedBits":0,"writeUndiv":false})
[2024-09-22 17:30:13] debug: zh:controller:endpoint: Request Queue (0xecf64cfffe35bb44/1): send request
[2024-09-22 17:30:13] debug: zh:ember: ~~~> [ZCL to=16413 apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":1,"destinationEndpoint":1,"options":4352,"groupId":0,"sequence":0} header={"frameControl":{"reservedBits":0,"frameType":1,"direction":1,"disableDefaultResponse":true,"manufacturerSpecific":false},"transactionSequenceNumber":39,"commandIdentifier":5}]
[2024-09-22 17:30:13] debug: zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=8 Len=89]
[2024-09-22 17:30:13] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=1](ackRx=0)
[2024-09-22 17:30:13] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-09-22 17:30:13] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=0 frmTx=1)
[2024-09-22 17:30:13] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=1](frmRx=1) Added to rxQueue
[2024-09-22 17:30:13] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2](ackRx=1)
[2024-09-22 17:30:13] debug: zh:ember:ezsp: <=== [FRAME: ID=52:"SEND_UNICAST" Seq=8 Len=10]
[2024-09-22 17:30:13] debug: zh:ember:ezsp: ~~~> [SENT type=DIRECT apsSequence=191 messageTag=20 status=OK]
[2024-09-22 17:30:13] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-09-22 17:30:13] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=1 frmTx=1)
[2024-09-22 17:30:13] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=2](frmRx=2) Added to rxQueue
[2024-09-22 17:30:13] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3](ackRx=1)
[2024-09-22 17:30:13] debug: zh:ember:ezsp: <=== [CBFRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=8 Len=26]
[2024-09-22 17:30:13] debug: zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [status=OK], [type=DIRECT], [indexOrDestination=16413], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":1,"destinationEndpoint":1,"options":4352,"groupId":0,"sequence":191}], [messageTag=20]
[2024-09-22 17:30:14] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-09-22 17:30:14] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=1 frmTx=1)
[2024-09-22 17:30:14] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=3](frmRx=3) Added to rxQueue
[2024-09-22 17:30:14] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4](ackRx=1)
[2024-09-22 17:30:14] debug: zh:ember:ezsp: <=== [CBFRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=8 Len=54]
[2024-09-22 17:30:14] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":1,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":22}], [packetInfo:{"senderShortId":16413,"senderLongId":"0x0000000000000000","bindingIndex":255,"addressIndex":255,"lastHopLqi":0,"lastHopRssi":0,"lastHopTimestamp":25}], [messageContents=012803007c11cd1157000001683c01003f]
[2024-09-22 17:30:14] debug: zh:controller: Received payload: clusterID=25, address=16413, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=0, frame={"header":{"frameControl":{"frameType":1,"manufacturerSpecific":false,"direction":0,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":40,"commandIdentifier":3},"payload":{"fieldControl":0,"manufacturerCode":4476,"imageType":4557,"fileVersion":16777303,"fileOffset":81000,"maximumDataSize":63},"command":{"ID":3,"response":5,"parameters":[{"name":"fieldControl","type":32},{"name":"manufacturerCode","type":33},{"name":"imageType","type":33},{"name":"fileVersion","type":35},{"name":"fileOffset","type":35},{"name":"maximumDataSize","type":32}],"name":"imageBlockRequest"}}
[2024-09-22 17:30:14] debug: z2m: Received Zigbee message from 'Living Room Light Switch', type 'commandImageBlockRequest', cluster 'genOta', data '{"fieldControl":0,"fileOffset":81000,"fileVersion":16777303,"imageType":4557,"manufacturerCode":4476,"maximumDataSize":63}' from endpoint 1 with groupID 0
[2024-09-22 17:30:14] debug: zhc:ota:common: Request offsets: fileOffset=81000 pageOffset=0 maximumDataSize=63
[2024-09-22 17:30:14] debug: zhc:ota:common: Payload offsets: start=81000 end=81050 dataSize=50
[2024-09-22 17:30:14] debug: zh:controller:endpoint: CommandResponse 0xecf64cfffe35bb44/1 genOta.imageBlockResponse({"status":0,"manufacturerCode":4476,"imageType":4557,"fileVersion":16777303,"fileOffset":81000,"dataSize":50,"data":{"type":"Buffer","data":[19,251,7,168,32,240,5,249,128,35,16,34,173,248,30,48,6,171,205,233,2,66,205,233,0,66,4,147,41,70,10,75,7,168,29,240,136,252,4,70,7,168,32,240,215,254,28,177,209,33]}}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"reservedBits":0,"writeUndiv":false})
[2024-09-22 17:30:14] debug: zh:controller:endpoint: Request Queue (0xecf64cfffe35bb44/1): send request
[2024-09-22 17:30:14] debug: zh:ember: ~~~> [ZCL to=16413 apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":1,"destinationEndpoint":1,"options":4352,"groupId":0,"sequence":0} header={"frameControl":{"reservedBits":0,"frameType":1,"direction":1,"disableDefaultResponse":true,"manufacturerSpecific":false},"transactionSequenceNumber":40,"commandIdentifier":5}]
[2024-09-22 17:30:14] debug: zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=9 Len=89]
[2024-09-22 17:30:14] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=4](ackRx=1)
[2024-09-22 17:30:14] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-09-22 17:30:14] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=1 frmTx=2)
[2024-09-22 17:30:14] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=4](frmRx=4) Added to rxQueue
[2024-09-22 17:30:14] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5](ackRx=2)
[2024-09-22 17:30:14] debug: zh:ember:ezsp: <=== [FRAME: ID=52:"SEND_UNICAST" Seq=9 Len=10]
[2024-09-22 17:30:14] debug: zh:ember:ezsp: ~~~> [SENT type=DIRECT apsSequence=192 messageTag=21 status=OK]
[2024-09-22 17:30:14] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-09-22 17:30:14] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=2 frmTx=2)
[2024-09-22 17:30:14] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=5](frmRx=5) Added to rxQueue
[2024-09-22 17:30:14] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6](ackRx=2)
[2024-09-22 17:30:14] debug: zh:ember:ezsp: <=== [CBFRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=9 Len=26]
[2024-09-22 17:30:14] debug: zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [status=OK], [type=DIRECT], [indexOrDestination=16413], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":1,"destinationEndpoint":1,"options":4352,"groupId":0,"sequence":192}], [messageTag=21]
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=2 frmTx=2)
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=6](frmRx=6) Added to rxQueue
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7](ackRx=2)
[2024-09-22 17:30:15] debug: zh:ember:ezsp: <=== [CBFRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=9 Len=20]
[2024-09-22 17:30:15] debug: zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=11858], [sourceEui=0x8c6fb9fffec98a2a], [lastHopLqi=156], [lastHopRssi=-72], [relayCount=1], [relayList=61550]
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=2 frmTx=2)
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=7](frmRx=7) Added to rxQueue
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0](ackRx=2)
[2024-09-22 17:30:15] debug: zh:ember:ezsp: <=== [CBFRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=9 Len=45]
[2024-09-22 17:30:15] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1024,"sourceEndpoint":3,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":187}], [packetInfo:{"senderShortId":11858,"senderLongId":"0x0000000000000000","bindingIndex":255,"addressIndex":33,"lastHopLqi":45,"lastHopRssi":7,"lastHopTimestamp":1024}], [messageContents=18590a000021c20b]
[2024-09-22 17:30:15] debug: zh:controller: Received payload: clusterID=1024, address=11858, groupID=0, endpoint=3, destinationEndpoint=1, wasBroadcast=false, linkQuality=45, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":89,"commandIdentifier":10},"payload":[{"attrId":0,"dataType":33,"attrData":3010}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-09-22 17:30:15] debug: z2m: Received Zigbee message from '0x8c6fb9fffec98a2a', type 'attributeReport', cluster 'msIlluminanceMeasurement', data '{"measuredValue":3010}' from endpoint 3 with groupID 0
[2024-09-22 17:30:15] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/0x8c6fb9fffec98a2a', payload '{"battery":86,"illuminance":3010,"illuminance_lux":2,"linkquality":45,"occupancy":false,"update":{"installed_version":16777303,"latest_version":16777316,"state":"available"},"update_available":null}'
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=2 frmTx=2)
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=0](frmRx=0) Added to rxQueue
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1](ackRx=2)
[2024-09-22 17:30:15] debug: zh:ember:ezsp: <=== [CBFRAME: ID=89:"INCOMING_ROUTE_RECORD_HANDLER" Seq=9 Len=20]
[2024-09-22 17:30:15] debug: zh:ember:ezsp: ezspIncomingRouteRecordHandler(): callback called with: [source=21247], [sourceEui=0xd87a3bfffe0fea43], [lastHopLqi=255], [lastHopRssi=-38], [relayCount=1], [relayList=54978]
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=2 frmTx=2)
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1](frmRx=1) Added to rxQueue
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2](ackRx=2)
[2024-09-22 17:30:15] debug: zh:ember:ezsp: <=== [CBFRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=9 Len=54]
[2024-09-22 17:30:15] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":1,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":23}], [packetInfo:{"senderShortId":16413,"senderLongId":"0x0000000000000000","bindingIndex":255,"addressIndex":255,"lastHopLqi":0,"lastHopRssi":0,"lastHopTimestamp":25}], [messageContents=012903007c11cd11570000019a3c01003f]
[2024-09-22 17:30:15] debug: zh:controller: Received payload: clusterID=25, address=16413, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=0, frame={"header":{"frameControl":{"frameType":1,"manufacturerSpecific":false,"direction":0,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":41,"commandIdentifier":3},"payload":{"fieldControl":0,"manufacturerCode":4476,"imageType":4557,"fileVersion":16777303,"fileOffset":81050,"maximumDataSize":63},"command":{"ID":3,"response":5,"parameters":[{"name":"fieldControl","type":32},{"name":"manufacturerCode","type":33},{"name":"imageType","type":33},{"name":"fileVersion","type":35},{"name":"fileOffset","type":35},{"name":"maximumDataSize","type":32}],"name":"imageBlockRequest"}}
[2024-09-22 17:30:15] debug: z2m: Received Zigbee message from 'Living Room Light Switch', type 'commandImageBlockRequest', cluster 'genOta', data '{"fieldControl":0,"fileOffset":81050,"fileVersion":16777303,"imageType":4557,"manufacturerCode":4476,"maximumDataSize":63}' from endpoint 1 with groupID 0
[2024-09-22 17:30:15] debug: zhc:ota:common: Request offsets: fileOffset=81050 pageOffset=0 maximumDataSize=63
[2024-09-22 17:30:15] debug: zhc:ota:common: Payload offsets: start=81050 end=81100 dataSize=50
[2024-09-22 17:30:15] debug: zh:controller:endpoint: CommandResponse 0xecf64cfffe35bb44/1 genOta.imageBlockResponse({"status":0,"manufacturerCode":4476,"imageType":4557,"fileVersion":16777303,"fileOffset":81050,"dataSize":50,"data":{"type":"Buffer","data":[6,72,244,247,35,249,6,155,16,43,3,208,210,33,3,72,244,247,28,249,17,176,48,189,0,68,64,4,16,40,4,0,45,233,247,79,6,70,13,70,20,70,31,70,79,240,1,11,223,248]}}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"reservedBits":0,"writeUndiv":false})
[2024-09-22 17:30:15] debug: zh:controller:endpoint: Request Queue (0xecf64cfffe35bb44/1): send request
[2024-09-22 17:30:15] debug: zh:ember: ~~~> [ZCL to=16413 apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":1,"destinationEndpoint":1,"options":4352,"groupId":0,"sequence":0} header={"frameControl":{"reservedBits":0,"frameType":1,"direction":1,"disableDefaultResponse":true,"manufacturerSpecific":false},"transactionSequenceNumber":41,"commandIdentifier":5}]
[2024-09-22 17:30:15] debug: zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=10 Len=89]
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2](ackRx=2)
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=2 frmTx=3)
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=2](frmRx=2) Added to rxQueue
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3](ackRx=2)
[2024-09-22 17:30:15] debug: zh:ember:ezsp: <=== [CBFRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=9 Len=45]
[2024-09-22 17:30:15] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1024,"sourceEndpoint":3,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":75}], [packetInfo:{"senderShortId":21247,"senderLongId":"0x0000000000000000","bindingIndex":255,"addressIndex":32,"lastHopLqi":47,"lastHopRssi":7,"lastHopTimestamp":1024}], [messageContents=186a0a000021c20b]
[2024-09-22 17:30:15] debug: zh:controller: Received payload: clusterID=1024, address=21247, groupID=0, endpoint=3, destinationEndpoint=1, wasBroadcast=false, linkQuality=47, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"transactionSequenceNumber":106,"commandIdentifier":10},"payload":[{"attrId":0,"dataType":33,"attrData":3010}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}}
[2024-09-22 17:30:15] debug: z2m: Received Zigbee message from '0xd87a3bfffe0fea43', type 'attributeReport', cluster 'msIlluminanceMeasurement', data '{"measuredValue":3010}' from endpoint 3 with groupID 0
[2024-09-22 17:30:15] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/0xd87a3bfffe0fea43', payload '{"battery":86,"illuminance":3010,"illuminance_lux":2,"linkquality":47,"occupancy":false,"update":{"installed_version":16777303,"latest_version":16777316,"state":"available"},"update_available":null}'
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=2 frmTx=3)
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: Timer expired waiting for ACK for frmTx=3, ackRx=2
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3](ackRx=2)
[2024-09-22 17:30:15] debug: zh:ember:uart:ash: ---> [FRAME type=DATA_RETX frmReTx=2 frmRx=3](ackRx=2 frmTx=3)
[2024-09-22 17:30:16] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-09-22 17:30:16] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=2 frmTx=3)
[2024-09-22 17:30:16] debug: zh:ember:uart:ash: Timer expired waiting for ACK for frmTx=3, ackRx=2
[2024-09-22 17:30:16] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3](ackRx=2)
[2024-09-22 17:30:16] debug: zh:ember:uart:ash: ---> [FRAME type=DATA_RETX frmReTx=2 frmRx=3](ackRx=2 frmTx=3)
[2024-09-22 17:30:18] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-09-22 17:30:18] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=2 frmTx=3)
[2024-09-22 17:30:18] debug: zh:ember:uart:ash: Timer expired waiting for ACK for frmTx=3, ackRx=2
[2024-09-22 17:30:18] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3](ackRx=2)
[2024-09-22 17:30:18] debug: zh:ember:uart:ash: ---> [FRAME type=DATA_RETX frmReTx=2 frmRx=3](ackRx=2 frmTx=3)
[2024-09-22 17:30:20] debug: zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-09-22 17:30:20] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=2 frmTx=3)
[2024-09-22 17:30:20] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=3](frmRx=3) Added to rxQueue
[2024-09-22 17:30:20] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4](ackRx=2)
[2024-09-22 17:30:20] debug: zh:ember:ezsp: <=== [CBFRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=9 Len=54]
[2024-09-22 17:30:20] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":25,"sourceEndpoint":1,"destinationEndpoint":1,"options":64,"groupId":0,"sequence":24}], [packetInfo:{"senderShortId":16413,"senderLongId":"0x0000000000000000","bindingIndex":255,"addressIndex":255,"lastHopLqi":0,"lastHopRssi":0,"lastHopTimestamp":25}], [messageContents=012a03007c11cd11570000019a3c01003f]
[2024-09-22 17:30:20] debug: zh:controller: Received payload: clusterID=25, address=16413, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=0, frame={"header":{"frameControl":{"frameType":1,"manufacturerSpecific":false,"direction":0,"disableDefaultResponse":false,"reservedBits":0},"transactionSequenceNumber":42,"commandIdentifier":3},"payload":{"fieldControl":0,"manufacturerCode":4476,"imageType":4557,"fileVersion":16777303,"fileOffset":81050,"maximumDataSize":63},"command":{"ID":3,"response":5,"parameters":[{"name":"fieldControl","type":32},{"name":"manufacturerCode","type":33},{"name":"imageType","type":33},{"name":"fileVersion","type":35},{"name":"fileOffset","type":35},{"name":"maximumDataSize","type":32}],"name":"imageBlockRequest"}}
[2024-09-22 17:30:20] debug: z2m: Received Zigbee message from 'Living Room Light Switch', type 'commandImageBlockRequest', cluster 'genOta', data '{"fieldControl":0,"fileOffset":81050,"fileVersion":16777303,"imageType":4557,"manufacturerCode":4476,"maximumDataSize":63}' from endpoint 1 with groupID 0
[2024-09-22 17:30:21] debug: zh:ember:uart:ash: <--- [FRAME type=ERROR]
[2024-09-22 17:30:21] error: zh:ember:uart:ash: Received ERROR from adapter, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-09-22 17:30:21] error: zh:ember:uart:ash: ASH disconnected | Adapter status: ASH_NCP_FATAL_ERROR
[2024-09-22 17:30:21] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
[2024-09-22 17:30:21] error: zh:ember: Adapter fatal error: HOST_FATAL_ERROR
[2024-09-22 17:30:21] debug: zh:controller: Adapter disconnected
[2024-09-22 17:30:21] info: zh:ember:uart:ash: ASH COUNTERS since last clear:
[2024-09-22 17:30:21] info: zh:ember:uart:ash: Total frames: RX=5585, TX=7375
[2024-09-22 17:30:21] info: zh:ember:uart:ash: Cancelled : RX=0, TX=0
[2024-09-22 17:30:21] info: zh:ember:uart:ash: DATA frames : RX=5580, TX=1803
[2024-09-22 17:30:21] info: zh:ember:uart:ash: DATA bytes : RX=165234, TX=148276
[2024-09-22 17:30:21] info: zh:ember:uart:ash: Retry frames: RX=3, TX=3
[2024-09-22 17:30:21] info: zh:ember:uart:ash: ACK frames : RX=0, TX=5568
[2024-09-22 17:30:21] info: zh:ember:uart:ash: NAK frames : RX=0, TX=0
[2024-09-22 17:30:21] info: zh:ember:uart:ash: nRdy frames : RX=0, TX=0
[2024-09-22 17:30:21] info: zh:ember:uart:ash: CRC errors : RX=0
[2024-09-22 17:30:21] info: zh:ember:uart:ash: Comm errors : RX=0
[2024-09-22 17:30:21] info: zh:ember:uart:ash: Length < minimum: RX=0
[2024-09-22 17:30:21] info: zh:ember:uart:ash: Length > maximum: RX=0
[2024-09-22 17:30:21] info: zh:ember:uart:ash: Bad controls : RX=0
[2024-09-22 17:30:21] info: zh:ember:uart:ash: Bad lengths : RX=0
[2024-09-22 17:30:21] info: zh:ember:uart:ash: Bad ACK numbers : RX=0
[2024-09-22 17:30:21] info: zh:ember:uart:ash: Out of buffers : RX=0
[2024-09-22 17:30:21] info: zh:ember:uart:ash: Retry dupes : RX=3
[2024-09-22 17:30:21] info: zh:ember:uart:ash: Out of sequence : RX=0
[2024-09-22 17:30:21] info: zh:ember:uart:ash: ACK timeouts : RX=3
[2024-09-22 17:30:29] debug: zh:ember:ezsp: =x=> [FRAME: ID=52:"SEND_UNICAST" Seq=10 Len=89] Error: ASH_ERROR_TIMEOUTS
[2024-09-22 17:30:29] error: zh:ember:ezsp: ERROR Transaction failure; status=ASH_ERROR_TIMEOUTS. Last Frame: [FRAME: ID=52:"SEND_UNICAST" Seq=9 Len=10].
[2024-09-22 17:30:29] debug: zh:controller:endpoint: Request Queue (0xecf64cfffe35bb44/1): queue request (transaction failed) (Error: ~x~> [ZCL to=16413] Failed to send request with status=FAIL.)
[2024-09-22 17:30:29] debug: zh:controller:requestqueue: Request Queue (0xecf64cfffe35bb44/1): Sending when active. Expires: 1727058615394
[2024-09-22 17:30:50] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Entrance Motion Sensor', payload '{"battery":100,"device_temperature":34,"illuminance":0,"illuminance_lux":0,"linkquality":234,"occupancy":false,"power_outage_count":122,"voltage":3015}'
[2024-09-22 17:30:51] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/Kitchen Motion Sensor', payload '{"battery":100,"device_temperature":34,"illuminance":8,"illuminance_lux":8,"linkquality":236,"occupancy":false,"power_outage_count":159,"voltage":3015}'
[2024-09-22 17:30:51] info: zh:ember:uart:ash: Port closed.
[2024-09-22 17:30:51] info: zh:ember:uart:ash: ======== ASH stopped ========
[2024-09-22 17:30:51] info: zh:ember:ezsp: ======== EZSP stopped ========
[2024-09-22 17:30:51] info: zh:ember: ======== Ember Adapter Stopped ========
[2024-09-22 17:30:51] error: z2m: Adapter disconnected, stopping
[2024-09-22 17:30:51] debug: z2m: Saving state to file /app/data/state.json
[2024-09-22 17:30:51] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload '{"state":"offline"}'
[2024-09-22 17:30:51] info: z2m: Disconnecting from MQTT server
[2024-09-22 17:30:51] info: z2m: Stopping zigbee-herdsman...
[2024-09-22 17:30:51] debug: zh:controller:database: Writing database to '/app/data/database.db'
[2024-09-22 17:30:51] info: z2m: Stopped zigbee-herdsman
[2024-09-22 17:30:51] info: z2m: Stopped Zigbee2MQTT
Crash on multiple OTAs is not really surprising; it's entirely dependent on the stability of the underlaying network (quality of the routers, number of hops, etc.).
Can you list the devices you have on your network (don't care about IEEE/nwk, just the models)?
How far away from the coordinator is that last device you tried to update? What are the chances that it's connected through a router, not directly?
Can you post a screenshot of the network map (try to make it as legible as possible)? At least the path from the coordinator to the device you tried to update last.
You can also try to lower the adapter_concurrent option, see how that goes (default is 16, try 8). docs
Crash on multiple OTAs is not really surprising; it's entirely dependent on the stability of the underlaying network (quality of the routers, number of hops, etc.).
Oh yea, I just wanted to try to stress it a bit.
Can you list the devices you have on your network (don't care about IEEE/nwk, just the models)?
| 1 | 0x5cc7c1fffe5ddcb8 | IKEA E2001 | E2002 | 122 |
| 2 | 0x8c6fb9fffec98a2a | IKEA | E2134 | 37 |
| 3 | 0xd87a3bfffe0fea43 | IKEA | E2134 | 38 |
| 4 | Office Light Switch | IKEA | E2201 | 0 |
| 5 | Kitchen Light Switch | IKEA | E2201 | 0 |
| 6 | Hallway Light Switch | IKEA | E2201 | 255 |
| 7 | Server Room Light Switch | IKEA | E2201 | 0 |
| 8 | Bedroom Light Switch | IKEA | E2201 | 0 |
| 9 | Living Room Light Switch | IKEA | E2201 | 0 |
| 10 | Entrance Light Switch | IKEA | E2201 | 0 |
| 11 | Bathroom Light Switch | IKEA | E2201 | 0 |
| 12 | Bedroom Light Bulb | IKEA | LED2109G6 | 14 |
| 13 | Entrance Light Bulb | IKEA | LED2109G6 | 15 |
| 14 | Kitchen Light Bulb | IKEA | LED2109G6 | 16 |
| 15 | Living Room Light Bulb | IKEA | LED2109G6 | 0 |
| 16 | Office Light Bulb | IKEA | LED2109G6 | 0 |
| 17 | Server Room Light Bulb | IKEA | LED2109G6 | 0 |
| 18 | Bathroom Mirror Light Bulb | IKEA | LED2109G6 | 0 |
| 19 | Bathroom Light Bulb | IKEA | LED2109G6 | 28 |
| 20 | Hallway Light Bulb | IKEA | LED2111G6 | 13 |
| 21 | some-long-random-id | Aqara | MCCGQ11LM | 104 |
| 22 | 0x00158d000ae4e67f | Aqara | MCCGQ11LM | 9 |
| 23 | Living Room Door (Right Side) | Aqara | MCCGQ11LM | 193 |
| 24 | Server Room Door (Right Side) | Aqara | MCCGQ11LM | 103 |
| 25 | Server Room Door (Left Side) | Aqara | MCCGQ11LM | 21 |
| 26 | Living Room Door (Left Side) | Aqara | MCCGQ11LM | 123 |
| 27 | Office Side Window (Left Side) | Aqara | MCCGQ11LM | 103 |
| 28 | 0x00158d000ae4cd81 | Aqara | MCCGQ11LM | 128 |
| 29 | Kitchen Window (Left Side) | Aqara | MCCGQ11LM | 56 |
| 30 | Office Side Window (Right Side) | Aqara | MCCGQ11LM | 203 |
| 31 | Office Rear Window (Left Side) | Aqara | MCCGQ11LM | 11 |
| 32 | Office Rear Window (Right Side) | Aqara | MCCGQ11LM | 11 |
| 33 | Main Door | Aqara | MCCGQ11LM | 12 |
| 34 | Kitchen Window (Right Side) | Aqara | MCCGQ11LM | 200 |
| 35 | Bedroom Door (Right Side) | Aqara | MCCGQ11LM | 71 |
| 36 | Bedroom Door (Left Side) | Aqara | MCCGQ11LM | 7 |
| 37 | Magic Cube | Aqara | MFKZQ01LM | 108 |
| 38 | Entrance Motion Sensor | Aqara | RTCGQ11LM | 30 |
| 39 | Kitchen Motion Sensor | Aqara | RTCGQ11LM | 25 |
How far away from the coordinator is that last device you tried to update?
Like 1-2meters.
What are the chances that it's connected through a router, not directly?
So the coordinator is on my server on the rack ~1-2meters away. Above the rack there is a bulb, the switch I was upgrading is at my desk (1-2meters from the rack) And right above the desk is a bulb.
Can you post a screenshot of the network map (try to make it as legible as possible)? At least the path from the coordinator to the device you tried to update last.
The device I was upgrading is the Living Room Light Switch
Which seems to be connected via the Server Room Light Bulb
You can also try to lower the
adapter_concurrentoption, see how that goes (default is 16, try 8). docs
I'll try that soon
EDIT: Re-paired that switch allowing only coordinator to join. And retesting the update
Single update stopped at 66.5% with the same error again. It was direct connected to the coordinator. I'll now try changing the adapter_concurrent
Concurrency of 8
error 2024-09-22 20:41:37zh:ember:uart:ash: Received ERROR from adapter, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
error 2024-09-22 20:41:37zh:ember:uart:ash: ASH disconnected | Adapter status: ASH_NCP_FATAL_ERROR
error 2024-09-22 20:41:37zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR.
error 2024-09-22 20:41:37zh:ember: Adapter fatal error: HOST_FATAL_ERROR
info 2024-09-22 20:41:37zh:ember:uart:ash: ASH COUNTERS since last clear:
info 2024-09-22 20:41:37zh:ember:uart:ash: Total frames: RX=2250, TX=3001
info 2024-09-22 20:41:37zh:ember:uart:ash: Cancelled : RX=0, TX=0
info 2024-09-22 20:41:37zh:ember:uart:ash: DATA frames : RX=2245, TX=752
info 2024-09-22 20:41:37zh:ember:uart:ash: DATA bytes : RX=65862, TX=62421
info 2024-09-22 20:41:37zh:ember:uart:ash: Retry frames: RX=3, TX=3
info 2024-09-22 20:41:37zh:ember:uart:ash: ACK frames : RX=0, TX=2245
info 2024-09-22 20:41:37zh:ember:uart:ash: NAK frames : RX=0, TX=0
info 2024-09-22 20:41:37zh:ember:uart:ash: nRdy frames : RX=0, TX=0
info 2024-09-22 20:41:37zh:ember:uart:ash: CRC errors : RX=0
info 2024-09-22 20:41:37zh:ember:uart:ash: Comm errors : RX=0
info 2024-09-22 20:41:37zh:ember:uart:ash: Length < minimum: RX=0
info 2024-09-22 20:41:37zh:ember:uart:ash: Length > maximum: RX=0
info 2024-09-22 20:41:37zh:ember:uart:ash: Bad controls : RX=0
info 2024-09-22 20:41:37zh:ember:uart:ash: Bad lengths : RX=0
info 2024-09-22 20:41:37zh:ember:uart:ash: Bad ACK numbers : RX=0
info 2024-09-22 20:41:37zh:ember:uart:ash: Out of buffers : RX=0
info 2024-09-22 20:41:37zh:ember:uart:ash: Retry dupes : RX=3
info 2024-09-22 20:41:37zh:ember:uart:ash: Out of sequence : RX=0
info 2024-09-22 20:41:37zh:ember:uart:ash: ACK timeouts : RX=3
error 2024-09-22 20:41:45zh:ember:ezsp: ERROR Transaction failure; status=ASH_ERROR_TIMEOUTS. Last Frame: [FRAME: ID=52:"SEND_UNICAST" Seq=238 Len=10].
info 2024-09-22 20:42:07zh:ember:uart:ash: Port closed.
info 2024-09-22 20:42:07zh:ember:uart:ash: ======== ASH stopped ========
info 2024-09-22 20:42:07zh:ember:ezsp: ======== EZSP stopped ========
info 2024-09-22 20:42:07zh:ember: ======== Ember Adapter Stopped ========
error 2024-09-22 20:42:07z2m: Adapter disconnected, stopping
This is the same behavior I have. It looks like an OTA is the "easiest" way to trigger this issue - you need a device to update, or course. I also tried placing sensors just besides the coordinator (20cm from the coordinator antenna) and it doesn't help, so I'm not sure how the rest of the network influences in this issue.
@alexborro Does your network map also look similar to the one above (many devices directly on the coordinator)?
@alexborro Does your network map also look similar to the one above (many devices directly on the coordinator)?
I don't think so, because my coordinator needs to be placed in a corner of my house and then I need to rely on routers.
This is a map of the network and you can see almost all end-devices are connected to a router, not to the coordinator.
(Sorry the names are not in English, but almost all routers are lights, the majority are Ikea and philips lights)
After carefully checking it, almost all routers have direct connection to the coordinator (LQI 100+), maybe because the coordinator has a good antenna (SMLight 06M with 5dB antenna), but the end-devices are definitely connected through routers, as you can see in the picture above.
I updated the firmware on my Sonoff adapter to Ember 7.4.4 GA. It's been 3 days, and so far, everything is okay. There are some minor reconnections with the switches, but no disconnections so far. I’ll keep monitoring and report back later.
@stavros-k Could you try with 7.4.4, see if you can make it crash like you did before? I don't see anything in the release notes from silabs that would explain this. If it works, can you also confirm with 8.0.2 since I'd expect them to be somewhat aligned (at least on bug fixes...).
With a 7.4.4 is the first time I managed to complete a single OTA update. I'll try now 8.0.2.
8.0.2 crashed with 2 OTA updates. Retrying with 1 and will go back to 7.4.4 and try 2 updates there.
8.0.2 crashed with 1 OTA update. Going back to 7.4.4 to try 2 OTA updates
7.4.4 crashed with 2 OTA updates But 1 OTA works everytime. Updating now the 4th device. Up until now, not even 1 was successful.
@Nerivec
Thanks for the detailed feedback! Looks like something in 7.4.4 is making your OTAs happier... too bad silabs release notes don't really point to something in that regard...
Thanks for the detailed feedback! Looks like something in 7.4.4 is making your OTAs happier... too bad silabs release notes don't really point to something in that regard...
I do have an order coming for an SMLIGHT, but happy I got the sonoff working in the mean time! Thanks for the help
Nice that you mentioned the SMLight. I have the 06M and it is running the latest SMLight firmware, which is "20240510". I guess it is the 7.4.1 because the build data matches. And I'm assuming that if I want to flash a new one, I have to manually download and flash from https://github.com/darkxst/silabs-firmware-builder/tree/main/firmware_builds/slzb-06m or ask SMLight to make it available throught 06M OTA Interface, right?
Worked for 7 days without disconnections, I can say that the 7.4.4 firmware solved my reconnection issue. The only thing I noticed was after I changed the antenna to a 6 dBi one, I started getting a lot of errors with my switches. I had to revert back to the stock antenna.
7.4.4 with increased buffers
You mean custom firmware? If yes, what increased values exactly?
Note: That error is not necessarily a firmware issue, but could just be generic network failure depending on the scenario.
7.4.4 with increased buffers
You mean custom firmware? If yes, what increased values exactly?
+ SL_IOSTREAM_USART_VCOM_RX_BUFFER_SIZE: 64
+ SL_ZIGBEE_NEIGHBOR_TABLE_SIZE: 26
+ SL_ZIGBEE_SOURCE_ROUTE_TABLE_SIZE: 200
Note: That error is not necessarily a firmware issue, but could just be generic network failure depending on the scenario.
Yes, this is most likely an indication of a busy radio channel. the problem is that this is not handled as a normal situation, but puts the z2m into a reboot cycle.