Koenkk / zigbee2mqtt

Zigbee 🐝 to MQTT bridge πŸŒ‰, get rid of your proprietary Zigbee bridges πŸ”¨
https://www.zigbee2mqtt.io
GNU General Public License v3.0
12.17k stars 1.68k forks source link

ROUTE_ERROR_ADDRESS_CONFLICT #22271

Closed fred-gb closed 6 months ago

fred-gb commented 7 months ago

What happened?

I get lots of error logs lines=

Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".

And many devices are unusable. Pass to timeout state and back.

These modules, no communication anymore. https://www.zigbee2mqtt.io/devices/PIR313-E.html

Network is slow, lot of timeouts.

And when I get back to driver eszp and my second backup Sonoff ZBDongle-E (under 7.3 firmware), my zigbee network is working normally again.

I know in life we as to do somes choices, but between switches PTM216 and multisensor PIR313-E, it's difficult to decide!

What did you expect to happen?

For operating PTM216 switches, I follow this tutorial: https://github.com/Koenkk/zigbee2mqtt/discussions/21462

How to reproduce it (minimal and precise)

Zigbee2MQTT version

1.36.1

Adapter firmware version

7.4.1 [GA]

Adapter

Sonoff ZBDongle-E

Setup

LXC container Ubuntu, Nomad as orchestrator, Z2M Docker version

Debug log

Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".

When I try to wakeup device on battery:

024-04-20 17:12:08Failed to configure '0x3c6a2cfffed22b52', attempt 1 (Error: Bind 0x3c6a2cfffed22b52/2 msIlluminanceMeasurement from '0xe8e07efffeefa989/1' failed (Delivery failed for {"profileId":0,"clusterId":33,"sourceEndpoint":0,"destinationEndpoint":0,"options":4160,"groupId":0,"sequence":126}) at EmberOneWaitress.deliveryFailedFor (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/oneWaitress.ts:94:31) at EmberAdapter.onMessageSentDeliveryFailed (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:556:30) at Ezsp.emit (node:events:517:28) at Ezsp.ezspMessageSentHandler (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:3960:18) at Ezsp.callbackDispatch (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:804:18) at Ezsp.tick (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:461:18) at listOnTimeout (node:internal/timers:569:17) at processTimers (node:internal/timers:512:7))

When I activate "Permit join"

[ZDO] Failed permit joining request with status=NETWORK_BUSY.
[ZDO] Failed permit joining request with status=NETWORK_BUSY.
[ZDO] Failed permit joining request with status=NETWORK_BUSY.
[ZDO] Failed permit joining request with status=NETWORK_BUSY.
[ZDO] Failed permit joining request with status=NETWORK_BUSY.
~x~> [ZCL BROADCAST] Failed to send with status=NETWORK_BUSY.
~x~> [ZCL BROADCAST] Failed to send with status=NETWORK_BUSY.
~x~> [ZCL BROADCAST] Failed to send with status=NETWORK_BUSY.
~x~> [ZCL BROADCAST] Failed to send with status=NETWORK_BUSY.
Failed to read zigbee attributes: Error: Cluster 'liXeePrivate' has no attribute 'motDEtat'
~x~> [ZCL BROADCAST] Failed to send with status=NETWORK_BUSY.
~x~> [ZCL BROADCAST] Failed to send with status=NETWORK_BUSY.
~x~> [ZCL BROADCAST] Failed to send with status=NETWORK_BUSY.
~x~> [ZCL BROADCAST] Failed to send with status=NETWORK_BUSY.
Outsidewall commented 6 months ago

Hello, Have you tried updating the dongle's firmware to 7.4.2, I had many errors with 7.4.1 the uplift fixed them.

fred-gb commented 6 months ago

😞

With latest-devsame errors

error 2024-04-26 17:59:27Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":251} messageTag=255]
warning 2024-04-26 17:59:29Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".

and docker logs

[2024-04-26 19:00:07] debug:    zh:ember:ezsp: ezspIncomingNetworkStatusHandler(): callback called with: [errorCode=ROUTE_ERROR_ADDRESS_CONFLICT], [target=0]
[2024-04-26 19:00:07] warning:  zh:ember:ezsp: Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
[2024-04-26 19:00:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-04-26 19:00:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-04-26 19:00:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=0] Added to rxQueue
[2024-04-26 19:00:07] debug:    zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1]
[2024-04-26 19:00:07] debug:    zh:ember:ezsp: <=== [FRAME: ID=196:"INCOMING_NETWORK_STATUS_HANDLER" Seq=51 Len=8]
[2024-04-26 19:00:07] debug:    zh:ember:ezsp: ezspIncomingNetworkStatusHandler(): callback called with: [errorCode=ROUTE_ERROR_ADDRESS_CONFLICT], [target=0]
[2024-04-26 19:00:07] warning:  zh:ember:ezsp: Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
[2024-04-26 19:00:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-04-26 19:00:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-04-26 19:00:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=1] Added to rxQueue
[2024-04-26 19:00:07] debug:    zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2]
[2024-04-26 19:00:07] debug:    zh:ember:ezsp: <=== [FRAME: ID=196:"INCOMING_NETWORK_STATUS_HANDLER" Seq=51 Len=8]
[2024-04-26 19:00:07] debug:    zh:ember:ezsp: ezspIncomingNetworkStatusHandler(): callback called with: [errorCode=ROUTE_ERROR_ADDRESS_CONFLICT], [target=0]
[2024-04-26 19:00:07] warning:  zh:ember:ezsp: Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
[2024-04-26 19:00:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-04-26 19:00:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-04-26 19:00:07] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=2] Added to rxQueue
[2024-04-26 19:00:07] debug:    zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3]
[2024-04-26 19:00:07] debug:    zh:ember:ezsp: <=== [FRAME: ID=196:"INCOMING_NETWORK_STATUS_HANDLER" Seq=51 Len=8]
[2024-04-26 19:00:07] debug:    zh:ember:ezsp: ezspIncomingNetworkStatusHandler(): callback called with: [errorCode=ROUTE_ERROR_ADDRESS_CONFLICT], [target=0]
[2024-04-26 19:00:07] warning:  zh:ember:ezsp: Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
[2024-04-26 19:00:10] debug:    z2m: Saving state to file /app/data/state.json
[2024-04-26 19:00:12] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-04-26 19:00:12] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-04-26 19:00:12] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue
[2024-04-26 19:00:12] debug:    zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4]
[2024-04-26 19:00:12] debug:    zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=51 Len=40]
[2024-04-26 19:00:12] debug:    zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":222}], [lastHopLqi=76], [lastHopRssi=175], [sender=4754], [bindingIndex=255], [addressIndex=255], [messageContents=081b0a01002045e2ff201fe4ff2000]
[2024-04-26 19:00:12] debug:    zh:controller: Data is from unknown device with address '4754', skipping...
[2024-04-26 19:00:18] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-04-26 19:00:18] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-04-26 19:00:18] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=4] Added to rxQueue
[2024-04-26 19:00:18] debug:    zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5]
[2024-04-26 19:00:18] debug:    zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=51 Len=39]
[2024-04-26 19:00:18] debug:    zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":197}], [lastHopLqi=52], [lastHopRssi=169], [sender=22388], [bindingIndex=255], [addressIndex=255], [messageContents=08120a010020c0e2ff2036e4ff2000]
[2024-04-26 19:00:18] debug:    zh:controller: Data is from unknown device with address '22388', skipping...

😭

fred-gb commented 6 months ago

I tried today on my "production" site to switch with dongle with 7.4.2 firmware and the latest-dev docker images.

And I have lot of errors, I can't use devices on battery.

When I try to open network to new device:

error 2024-04-27 09:02:42[ZDO] Failed permit joining request with status=NETWORK_BUSY.
error 2024-04-27 09:02:42~x~> [ZCL BROADCAST] Failed to send with status=NETWORK_BUSY.

And conflict errors.

I have 55 devices on my network.

Unusable... 😭

Outsidewall commented 6 months ago

@fred-gb You might have some sort of network storm going on, I wonder if removing the devices from power/unpluging them, restart the docker container, and carefully put them back one at a time, maybe one of them is causing the issue.

Nerivec commented 6 months ago

Since address 0 is the reserved address for the coordinator (adapter), seems something is very wrong/strange. Having two of these would definitely create all sorts of issues.

Can you check Z2M frontend and give me the list of addresses you see in "IEEE Address" column (both)? Also try getting some debug level logs from a cold start of Z2M (set to debug level before you start/restart) and running for about 15minutes after that. If you are using latest release (1.37), logs are all in one place, you just need to set the level to debug.

fred-gb commented 6 months ago

Thanks @Nerivec

I restart one dev plateform.

This is a docker-compose:

version: '3.8'
services:
  zigbee2mqtt:
    container_name: zigbee2mqtt
    image: koenkk/zigbee2mqtt:1.37.0
      # image: koenkk/zigbee2mqtt:latest-dev
    restart: unless-stopped
    volumes:
      - ./z2m:/app/data
      - /run/udev:/run/udev:ro
    ports:
      # Frontend port
      - 8080:8080
    environment:
      - TZ=Europe/Paris
    devices:
      # Make sure this matched your adapter location
      - /dev/serial/by-id/usb-ITEAD_SONOFF_Zigbee_3.0_USB_Dongle_Plus_V2_20240219194401-if00:/dev/ttyACM0

  mosquitto:
    image: eclipse-mosquitto
    hostname: mosquitto
    container_name: mosquitto
    restart: unless-stopped
    ports:
      - "1883:1883"
      - "9001:9001"
    volumes:
      - ./mosquitto:/etc/mosquitto
      - ./mosquitto/mosquitto.conf:/mosquitto/config/mosquitto.conf

Z2M configuration:

homeassistant: false
availability: true
advanced:
  log_level: debug
  homeassistant_legacy_entity_attributes: false
  legacy_api: false
  legacy_availability_payload: false
permit_join: false
frontend:
  port: 8080
  host: 0.0.0.0
  auth_token: zigbee2mqtt
  url: http://192.168.10.116:8080
mqtt:
  base_topic: zigbee2mqtt
  server: mqtt://192.168.10.116
  user: admin
  password: admin
serial:
  port: /dev/ttyACM0
  adapter: ember
device_options:
  legacy: false
devices:
  '0xa49e69fffe051947':
    friendly_name: '0xa49e69fffe051947'

My Z2M frontend:

Capture d’écran 2024-05-02 aΜ€ 16 47 46

So. With all this new dev install I try to pair a new module: TO-Q-SY2-163JZT

Pairing works, but after, commands do not work.

This logs after somes minutes:

info 2024-05-02 16:12:08Zigbee: disabling joining new devices.
info 2024-05-02 16:12:08[STACK STATUS] Network closed.
error 2024-05-02 16:12:09Delivery of BROADCAST failed for "65532" [apsFrame={"profileId":0,"clusterId":54,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":79} messageTag=5]
error 2024-05-02 16:12:09Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":78} messageTag=255]
info 2024-05-02 16:12:12Zigbee: allowing new devices to join.
info 2024-05-02 16:12:12[STACK STATUS] Network opened.
error 2024-05-02 16:12:13Delivery of BROADCAST failed for "65532" [apsFrame={"profileId":0,"clusterId":54,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":80} messageTag=255]
error 2024-05-02 16:12:13Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":81} messageTag=6]
info 2024-05-02 16:12:48Interview for '0xa49e69fffe051947' started
info 2024-05-02 16:12:48Device '0xa49e69fffe051947' joined
info 2024-05-02 16:12:48Starting interview of '0xa49e69fffe051947'
warning 2024-05-02 16:13:15[ZDO] Node descriptor for "19448" reports device is only compliant to revision "22" of the ZigBee specification (current revision: 23).
warning 2024-05-02 16:13:16Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
info 2024-05-02 16:13:17Succesfully interviewed '0xa49e69fffe051947'
info 2024-05-02 16:13:17Successfully interviewed '0xa49e69fffe051947', device has successfully been paired
info 2024-05-02 16:13:17Device '0xa49e69fffe051947' is supported, identified as: TONGOU Smart circuit breaker (TO-Q-SY2-163JZT)
info 2024-05-02 16:13:17Configuring '0xa49e69fffe051947'
warning 2024-05-02 16:13:17Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
error 2024-05-02 16:13:22Failed to configure '0xa49e69fffe051947', attempt 1 (Error: Bind 0xa49e69fffe051947/1 msTemperatureMeasurement from '0xe8e07efffeefa989/1' failed (Delivery failed for {"profileId":0,"clusterId":33,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":111}) at EmberOneWaitress.deliveryFailedFor (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/oneWaitress.ts:96:31) at EmberAdapter.onMessageSentDeliveryFailed (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:558:30) at Ezsp.emit (node:events:517:28) at Ezsp.ezspMessageSentHandler (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:3957:18) at Ezsp.callbackDispatch (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:794:18) at Ezsp.tick (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:448:22) at listOnTimeout (node:internal/timers:569:17) at processTimers (node:internal/timers:512:7))
info 2024-05-02 16:13:25Configuring '0xa49e69fffe051947'
error 2024-05-02 16:13:29Failed to configure '0xa49e69fffe051947', attempt 2 (Error: ZCL command 0xa49e69fffe051947/1 genBasic.read(["manufacturerName","zclVersion","appVersion","modelId","powerSource",65534], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":115}) at EmberOneWaitress.deliveryFailedFor (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/oneWaitress.ts:96:31) at EmberAdapter.onMessageSentDeliveryFailed (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:558:30) at Ezsp.emit (node:events:517:28) at Ezsp.ezspMessageSentHandler (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:3957:18) at Ezsp.callbackDispatch (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:794:18) at Ezsp.tick (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:448:22) at listOnTimeout (node:internal/timers:569:17) at processTimers (node:internal/timers:512:7))
info 2024-05-02 16:13:35Configuring '0xa49e69fffe051947'
error 2024-05-02 16:13:40Failed to configure '0xa49e69fffe051947', attempt 3 (Error: ZCL command 0xa49e69fffe051947/1 genBasic.read(["manufacturerName","zclVersion","appVersion","modelId","powerSource",65534], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":119}) at EmberOneWaitress.deliveryFailedFor (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/oneWaitress.ts:96:31) at EmberAdapter.onMessageSentDeliveryFailed (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:558:30) at Ezsp.emit (node:events:517:28) at Ezsp.ezspMessageSentHandler (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:3957:18) at Ezsp.callbackDispatch (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:794:18) at Ezsp.tick (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:448:22) at listOnTimeout (node:internal/timers:569:17) at processTimers (node:internal/timers:512:7))
error 2024-05-02 16:14:04Publish 'set' 'state' to '0xa49e69fffe051947' failed: 'Error: ZCL command 0xa49e69fffe051947/1 genOnOff.off({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":124})'
error 2024-05-02 16:14:09Publish 'set' 'state' to '0xa49e69fffe051947' failed: 'Error: ZCL command 0xa49e69fffe051947/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":125})'
error 2024-05-02 16:15:33Delivery of BROADCAST failed for "65532" [apsFrame={"profileId":0,"clusterId":54,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":128} messageTag=17]
error 2024-05-02 16:15:33Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":129} messageTag=33]
info 2024-05-02 16:16:26[STACK STATUS] Network closed.
error 2024-05-02 16:16:27Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":130} messageTag=34]
error 2024-05-02 16:16:27Delivery of BROADCAST failed for "65532" [apsFrame={"profileId":0,"clusterId":54,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":131} messageTag=18]
error 2024-05-02 16:35:01Publish 'set' 'state' to '0xa49e69fffe051947' failed: 'Error: ZCL command 0xa49e69fffe051947/1 genOnOff.off({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":151})'
error 2024-05-02 16:35:07Publish 'set' 'state' to '0xa49e69fffe051947' failed: 'Error: ZCL command 0xa49e69fffe051947/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":152})'
error 2024-05-02 16:41:02Publish 'set' 'state' to '0xa49e69fffe051947' failed: 'Error: ZCL command 0xa49e69fffe051947/1 genOnOff.off({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":159})'
error 2024-05-02 16:41:11Publish 'set' 'state' to '0xa49e69fffe051947' failed: 'Error: ZCL command 0xa49e69fffe051947/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":160})'
error 2024-05-02 16:42:02Publish 'set' 'state' to '0xa49e69fffe051947' failed: 'Error: ZCL command 0xa49e69fffe051947/1 genOnOff.off({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":170})'
error 2024-05-02 16:42:07Publish 'set' 'state' to '0xa49e69fffe051947' failed: 'Error: ZCL command 0xa49e69fffe051947/1 genOnOff.on({}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":false,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":171})'
info 2024-05-02 16:42:29Configuring '0xa49e69fffe051947'
error 2024-05-02 16:42:34Failed to configure '0xa49e69fffe051947', attempt 4 (Error: ZCL command 0xa49e69fffe051947/1 genBasic.read(["manufacturerName","zclVersion","appVersion","modelId","powerSource",65534], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":176}) at EmberOneWaitress.deliveryFailedFor (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/oneWaitress.ts:96:31) at EmberAdapter.onMessageSentDeliveryFailed (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:558:30) at Ezsp.emit (node:events:517:28) at Ezsp.ezspMessageSentHandler (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:3957:18) at Ezsp.callbackDispatch (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:794:18) at Ezsp.tick (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:448:22) at listOnTimeout (node:internal/timers:569:17) at processTimers (node:internal/timers:512:7))

The reconfiguration button does not work.

I try to apparing another device, a PIR313-E.

I'm unable to add to network. Interview failed. And make a loop:

info 2024-05-02 17:17:02Interview for '0x3c6a2cfffed22b98' started
info 2024-05-02 17:17:02Starting interview of '0x3c6a2cfffed22b98'
info 2024-05-02 17:17:18Removing device '0x3c6a2cfffed22b98' (block: false, force: true)
info 2024-05-02 17:17:18Successfully removed device '0x3c6a2cfffed22b98' (block: false, force: true)
info 2024-05-02 17:17:27Interview for '0x3c6a2cfffed22b98' started
info 2024-05-02 17:17:27Device '0x3c6a2cfffed22b98' joined
info 2024-05-02 17:17:27Starting interview of '0x3c6a2cfffed22b98'
info 2024-05-02 17:17:27Zigbee: allowing new devices to join.
error 2024-05-02 17:17:32Interview failed for '0x3c6a2cfffed22b98 with error 'Error: Interview failed because can not get active endpoints ('0x3c6a2cfffed22b98')'
error 2024-05-02 17:17:32Failed to interview '0x3c6a2cfffed22b98', device has not successfully been paired
info 2024-05-02 17:17:39Interview for '0x3c6a2cfffed22b98' started
info 2024-05-02 17:17:39Starting interview of '0x3c6a2cfffed22b98'
info 2024-05-02 17:17:47[STACK STATUS] Network opened.
error 2024-05-02 17:17:48Delivery of BROADCAST failed for "65532" [apsFrame={"profileId":0,"clusterId":54,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":88} messageTag=30]
warning 2024-05-02 17:17:53Device '0x3c6a2cfffed22b98' left the network
error 2024-05-02 17:18:18Interview failed for '0x3c6a2cfffed22b98 with error 'Error: DatabaseEntry with ID '3' does not exist'
error 2024-05-02 17:18:18Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":91} messageTag=37]
error 2024-05-02 17:18:33Interview failed for '0x3c6a2cfffed22b98 with error 'Error: DatabaseEntry with ID '3' does not exist'
info 2024-05-02 17:19:35Interview for '0x3c6a2cfffed22b98' started
info 2024-05-02 17:19:35Device '0x3c6a2cfffed22b98' joined
info 2024-05-02 17:19:35Starting interview of '0x3c6a2cfffed22b98'
error 2024-05-02 17:20:05Interview failed for '0x3c6a2cfffed22b98 with error 'Error: Interview failed because can not get active endpoints ('0x3c6a2cfffed22b98')'
error 2024-05-02 17:20:05Failed to interview '0x3c6a2cfffed22b98', device has not successfully been paired

CHANGE! While I write this post, I success pair the two devices, with this logs:

error 2024-05-02 17:25:21Interview failed for '0xa49e69fffe051947 with error 'Error: Delivery failed for {"profileId":0,"clusterId":4,"sourceEndpoint":0,"destinationEndpoint":0,"options":4160,"groupId":0,"sequence":162}'
error 2024-05-02 17:25:21Failed to interview '0xa49e69fffe051947', device has not successfully been paired
info 2024-05-02 17:25:26Interview for '0xa49e69fffe051947' started
info 2024-05-02 17:25:26Starting interview of '0xa49e69fffe051947'
error 2024-05-02 17:25:42Interview failed for '0xa49e69fffe051947 with error 'Error: Interview failed because can not get active endpoints ('0xa49e69fffe051947')'
error 2024-05-02 17:25:42Failed to interview '0xa49e69fffe051947', device has not successfully been paired
info 2024-05-02 17:25:47Succesfully interviewed '0x3c6a2cfffed22b98'
info 2024-05-02 17:25:47Successfully interviewed '0x3c6a2cfffed22b98', device has successfully been paired
info 2024-05-02 17:25:47Device '0x3c6a2cfffed22b98' is supported, identified as: OWON Motion sensor (PIR313-E)
info 2024-05-02 17:25:47Configuring '0x3c6a2cfffed22b98'
warning 2024-05-02 17:25:47Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
info 2024-05-02 17:25:50Successfully configured '0x3c6a2cfffed22b98'
info 2024-05-02 17:26:19Configuring '0xa49e69fffe051947'
error 2024-05-02 17:26:24Failed to configure '0xa49e69fffe051947', attempt 5 (Error: ZCL command 0xa49e69fffe051947/1 genBasic.read(["manufacturerName","zclVersion","appVersion","modelId","powerSource",65534], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":192}) at EmberOneWaitress.deliveryFailedFor (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/oneWaitress.ts:96:31) at EmberAdapter.onMessageSentDeliveryFailed (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:558:30) at Ezsp.emit (node:events:517:28) at Ezsp.ezspMessageSentHandler (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:3957:18) at Ezsp.callbackDispatch (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:794:18) at Ezsp.tick (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:448:22) at listOnTimeout (node:internal/timers:569:17) at processTimers (node:internal/timers:512:7))
info 2024-05-02 17:27:12Configuring '0xa49e69fffe051947'
error 2024-05-02 17:27:16Failed to configure '0xa49e69fffe051947', attempt 6 (Error: ZCL command 0xa49e69fffe051947/1 genBasic.read(["manufacturerName","zclVersion","appVersion","modelId","powerSource",65534], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":193}) at EmberOneWaitress.deliveryFailedFor (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/oneWaitress.ts:96:31) at EmberAdapter.onMessageSentDeliveryFailed (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:558:30) at Ezsp.emit (node:events:517:28) at Ezsp.ezspMessageSentHandler (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:3957:18) at Ezsp.callbackDispatch (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:794:18) at Ezsp.tick (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:448:22) at listOnTimeout (node:internal/timers:569:17) at processTimers (node:internal/timers:512:7))
warning 2024-05-02 17:27:27Device '0xa49e69fffe051947' left the network
error 2024-05-02 17:27:31~x~> [ZCL BROADCAST] Failed to send with status=NETWORK_BUSY.
error 2024-05-02 17:27:33Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":254} messageTag=255]
error 2024-05-02 17:27:34Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":199} messageTag=91]
error 2024-05-02 17:27:38Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":205} messageTag=255]
info 2024-05-02 17:28:02Interview for '0xa49e69fffe051947' started
info 2024-05-02 17:28:02Device '0xa49e69fffe051947' joined
info 2024-05-02 17:28:02Starting interview of '0xa49e69fffe051947'
warning 2024-05-02 17:28:17Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
info 2024-05-02 17:28:19Succesfully interviewed '0xa49e69fffe051947'
info 2024-05-02 17:28:19Successfully interviewed '0xa49e69fffe051947', device has successfully been paired
info 2024-05-02 17:28:19Device '0xa49e69fffe051947' is supported, identified as: TONGOU Smart circuit breaker (TO-Q-SY2-163JZT)
warning 2024-05-02 17:28:19Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
error 2024-05-02 17:28:25~x~> [ZCL BROADCAST] Failed to send with status=NETWORK_BUSY.
info 2024-05-02 17:28:32[STACK STATUS] Network closed.
error 2024-05-02 17:28:33Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":234} messageTag=117]
error 2024-05-02 17:28:33Delivery of BROADCAST failed for "65532" [apsFrame={"profileId":0,"clusterId":54,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":236} messageTag=58]

And come back from hell, the loop in error!

warning 2024-05-02 17:33:49Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
error 2024-05-02 17:33:56Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":38} messageTag=255]
error 2024-05-02 17:33:56Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":48} messageTag=255]
warning 2024-05-02 17:34:03Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
warning 2024-05-02 17:34:17Received network/route error ROUTE_ERROR_MANY_TO_ONE_ROUTE_FAILURE for "12040".
warning 2024-05-02 17:34:17Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
error 2024-05-02 17:35:31Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":219} messageTag=255]
error 2024-05-02 17:35:31Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":221} messageTag=255]
error 2024-05-02 17:35:31Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":217} messageTag=255]
warning 2024-05-02 17:35:48Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
error 2024-05-02 17:35:56Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":253} messageTag=255]
error 2024-05-02 17:36:01Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":3} messageTag=255]
error 2024-05-02 17:36:06Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":129} messageTag=255]
error 2024-05-02 17:36:06Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":7} messageTag=255]
error 2024-05-02 17:36:11Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":93} messageTag=255]
error 2024-05-02 17:36:16Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":21} messageTag=255]
warning 2024-05-02 17:36:18Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".
error 2024-05-02 17:36:21Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":182} messageTag=255]
error 2024-05-02 17:36:21Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":97} messageTag=255]
error 2024-05-02 17:36:46Delivery of BROADCAST failed for "65533" [apsFrame={"profileId":0,"clusterId":0,"sourceEndpoint":0,"destinationEndpoint":0,"options":1024,"groupId":0,"sequence":142} messageTag=255]
warning 2024-05-02 17:36:48Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".

Thanks if you can help me!

Nerivec commented 6 months ago

This is likely all linked to the 0 conflict. You will have to figure out which device is causing this strange behavior. I'm guessing the rest of your troubles will disappear after that.

I see you mentioned a "backup" adapter. If you have two adapters with the exact same network configuration, running at the same time, around the same location, that will definitely create issues. Unplug one when you run the other. Similarly, if you have two adapters made to run on the same network configuration, but they have different IEEE address, that can create issues if you swap back and forth.

If the above doesn't fix it, can you post the log file it created when you ran that last test?

Last resort, like @Outsidewall said, you may have to remove all devices and add them back one by one, until you find the culprit. I see you have a lixee device, try that one first; the zlinky_tic has caused plenty of troubles in the past.


Did you use the firmware from darkxst? If not, try that one ncp-uart-hw-v7.4.2.0-zbdonglee-115200.gbl I have yet to have time to test 7.4.2, though the changelog from silabs seems minimal. Still, you could try 7.4.1 instead if nothing else seems to work.

lettore commented 6 months ago

I have the same problem with EMBER driver, I thought something happened to my board while switching to 7.4.2 firmware but returning back to EZSP adapter mode in 1.37.0 version fixed all errors. I got the same Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0". error and plus a [ZDO clusterId=32799 sender=37662] Support not implemented upstream. In the meanwhile IKEA remote stopped working, but from the dashboard I was able to turn on or off devices. I also had some CRC errors at the start of the container, something I never seen before.

LDprg commented 6 months ago

Having same issue with the ember driver. I am using 7.4.2 firmware on and dongle-e. But only with Smoke detectors from Develco.

error:  z2m: Failed to interview '0x0015bc003101c7e8', device has not successfully been paired
error:  zh:controller: Interview failed for '0x0015bc003101c7e8 with error 'Error: Interview failed because can not get active endpoints ('0x0015bc003101c7e8')'
phenix1990 commented 6 months ago

Same here. I have a docker installation on a Pi5 with Sonof zigbee dongle-e.

I moved all files and devices from my previous pi4 and other zigbee stick to the new setup. Z2m is on version 1.37.0 Sonof firmware was first 7.4.1, same issues on 7.4.2 Moved same time from ezsp to ember

short time after booting i get 5 times per second: warning zh:ember:ezsp: Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0".

After a hour or two the network is dead with error error: zh:ember:uart:ash: Received ERROR from NCP, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT. error: zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR error: zh:ember:ezsp: [SEND COMMAND] Cannot send second one before processing response from first one.

Then i have to restart the container two make it work for another period.

Nerivec commented 6 months ago

@LDprg That's likely a battery-powered device that needs to wake up before it can configure properly. Try pushing a button on it before doing the configure. (You may need to push the button at 2-3 seconds intervals until it's done to keep it awake.)

Can someone with the Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0". issue provide a full debug-level log from z2m start to after that error starts occurring?


PS: Also, anyone not using a firmware from darkxst, please switch to it (Sonoff Dongle E 7.4.1). There has been issues with some others. https://github.com/Koenkk/zigbee2mqtt/discussions/21462#discussioncomment-8536401

phenix1990 commented 6 months ago

So i went back to ember driver with firmware 7.4.1 and debug level.

I dont know why but z2m crashed also with ezsp this evening with 7.4.2.

@Nerivec here are the loggings from container restart. Sorry for the long list, can I make this code fence scrollable in vertical?

Logs ``` [2024-05-04 20:28:44] info: z2m: Logging to console, file (filename: log.log) [2024-05-04 20:28:46] debug: z2m: Loaded state from file /app/data/state.json [2024-05-04 20:28:46] info: z2m: Starting Zigbee2MQTT version 1.37.0 (commit #46f34c8) [2024-05-04 20:28:46] info: z2m: Starting zigbee-herdsman (0.45.0) [2024-05-04 20:28:46] debug: z2m: Using zigbee-herdsman with settings: '{"adapter":{"concurrent":null,"delay":null,"disableLED":false},"backupPath":"/app/data/coordinator_backup.json","databaseBackupPath":"/app/data/database.db.backup","databasePath":"/app/data/database.db","network":{"channelList":[17],"extendedPanID":[221,221,221,221,221,221,221,221],"networkKey":"HIDDEN","panID":6759},"serialPort":{"adapter":"ember","path":"/dev/ttyACM0"}}' [2024-05-04 20:28:46] debug: zh:adapter: Path '/dev/ttyACM0' is valid for 'EmberAdapter' [2024-05-04 20:28:46] debug: zh:ember: Using delay=5. [2024-05-04 20:28:46] debug: zh:controller: Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":[49,5,217,11,55,130,46,153,234,181,181,103,180,130,229,235],"panID":6759,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[17]},"serialPort":{"path":"/dev/ttyACM0","adapter":"ember"},"databasePath":"/app/data/database.db","databaseBackupPath":"/app/data/database.db.backup","backupPath":"/app/data/coordinator_backup.json","adapter":{"disableLED":false,"concurrent":null,"delay":null}}' [2024-05-04 20:28:46] info: zh:ember: ======== Ember Adapter Starting ======== [2024-05-04 20:28:46] debug: zh:ember: Starting EZSP with stack configuration: "default". [2024-05-04 20:28:46] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-05-04 20:28:46] info: zh:ember:uart:ash: ======== ASH NCP reset ======== [2024-05-04 20:28:46] info: zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control. [2024-05-04 20:28:46] debug: zh:ember:uart:ash: Opening serial port with {"path":"/dev/ttyACM0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true} [2024-05-04 20:28:46] info: zh:ember:uart:ash: Serial port opened [2024-05-04 20:28:46] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-05-04 20:28:46] debug: zh:ember:uart:ash: ---> [FRAME type=RST] [2024-05-04 20:28:46] debug: zh:ember:uart:ash: Waiting for RSTACK... 0/2500 [2024-05-04 20:28:46] debug: zh:ember:uart:ash: Waiting for RSTACK... 100/2500 [2024-05-04 20:28:46] debug: zh:ember:uart:ash: Waiting for RSTACK... 200/2500 [2024-05-04 20:28:46] debug: zh:ember:uart:ash: Waiting for RSTACK... 300/2500 [2024-05-04 20:28:46] debug: zh:ember:uart:ash: Waiting for RSTACK... 400/2500 [2024-05-04 20:28:47] debug: zh:ember:uart:ash: Waiting for RSTACK... 500/2500 [2024-05-04 20:28:47] debug: zh:ember:uart:ash: Waiting for RSTACK... 600/2500 [2024-05-04 20:28:47] debug: zh:ember:uart:ash: Waiting for RSTACK... 700/2500 [2024-05-04 20:28:47] debug: zh:ember:uart:ash: Waiting for RSTACK... 800/2500 [2024-05-04 20:28:47] debug: zh:ember:uart:ash: Waiting for RSTACK... 900/2500 [2024-05-04 20:28:47] debug: zh:ember:uart:ash: Waiting for RSTACK... 1000/2500 [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=RSTACK] [2024-05-04 20:28:47] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-05-04 20:28:47] info: zh:ember:uart:ash: ======== ASH started ======== [2024-05-04 20:28:47] info: zh:ember:ezsp: ======== EZSP started ======== [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=0:"VERSION" Seq=0 Len=4] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=0:"VERSION" Seq=0 Len=7] [2024-05-04 20:28:47] debug: zh:ember: NCP info: EZSPVersion=13 StackType=2 StackVersion=29712 [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=170:"GET_VALUE" Seq=1 Len=6] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=170:"GET_VALUE" Seq=1 Len=14] [2024-05-04 20:28:47] debug: zh:ember: NCP version info: {"ezsp":13,"revision":"7.4.1 [GA]","build":0,"major":7,"minor":4,"patch":1,"special":0,"type":170} [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=2 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=2 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "ADDRESS_TABLE_SIZE" TO "16" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=3 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=3 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "TRUST_CENTER_ADDRESS_CACHE_SIZE" TO "2" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=4 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=4 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "INDIRECT_TRANSMISSION_TIMEOUT" TO "7680" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=5 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=5 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "MAX_HOPS" TO "30" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=6 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=6 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "TX_POWER_MODE" TO "32768" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=7 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=7 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "SUPPORTED_NETWORKS" TO "1" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=171:"SET_VALUE" Seq=8 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=171:"SET_VALUE" Seq=8 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspValueId] SET "END_DEVICE_KEEP_ALIVE_SUPPORT_MODE" TO "3" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=9 Len=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=9 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspPolicyId] SET "BINDING_MODIFICATION_POLICY" TO "18" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=10 Len=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=10 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspPolicyId] SET "MESSAGE_CONTENTS_IN_CALLBACK_POLICY" TO "65" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=171:"SET_VALUE" Seq=11 Len=9] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=171:"SET_VALUE" Seq=11 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspValueId] SET "MAXIMUM_INCOMING_TRANSFER_SIZE" TO "82,0" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=171:"SET_VALUE" Seq=12 Len=9] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=171:"SET_VALUE" Seq=12 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspValueId] SET "MAXIMUM_OUTGOING_TRANSFER_SIZE" TO "82,0" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=171:"SET_VALUE" Seq=13 Len=9] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=171:"SET_VALUE" Seq=13 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspValueId] SET "TRANSIENT_DEVICE_TIMEOUT" TO "16,39" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=21:"SET_MANUFACTURER_CODE" Seq=14 Len=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=21:"SET_MANUFACTURER_CODE" Seq=14 Len=5] [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=15 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=15 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "STACK_PROFILE" TO "2" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=16 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=16 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "SECURITY_LEVEL" TO "5" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=82:"GET_CONFIGURATION_VALUE" Seq=17 Len=6] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=82:"GET_CONFIGURATION_VALUE" Seq=17 Len=8] [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=18 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=18 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "BINDING_TABLE_SIZE" TO "32" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=19 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=19 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "KEY_TABLE_SIZE" TO "0" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=20 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=20 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "MAX_END_DEVICE_CHILDREN" TO "32" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=21 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=21 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "APS_UNICAST_MESSAGE_COUNT" TO "32" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=22 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=22 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "BROADCAST_TABLE_SIZE" TO "15" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=23 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=23 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "NEIGHBOR_TABLE_SIZE" TO "26" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=24 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=24 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "END_DEVICE_POLL_TIMEOUT" TO "8" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=25 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=25 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "TRANSIENT_KEY_TIMEOUT_S" TO "300" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=26 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=26 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "RETRY_QUEUE_SIZE" TO "16" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=27 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=27 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "SOURCE_ROUTE_TABLE_SIZE" TO "200" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=28 Len=8] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=28 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspConfigId] SET "MULTICAST_TABLE_SIZE" TO "16" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=29 Len=10] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=29 Len=9] [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=2:"ADD_ENDPOINT" Seq=30 Len=63] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=2:"ADD_ENDPOINT" Seq=30 Len=6] [2024-05-04 20:28:47] debug: zh:ember: Registered endpoint "1" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=31 Len=10] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=31 Len=6] [2024-05-04 20:28:47] debug: zh:ember: Registered multicast table entry: {"multicastId":0,"endpoint":1,"networkIndex":0}. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=32 Len=10] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=0] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=0] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=32 Len=6] [2024-05-04 20:28:47] debug: zh:ember: Registered multicast table entry: {"multicastId":901,"endpoint":1,"networkIndex":0}. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=33 Len=10] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=1] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=1] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=33 Len=9] [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=2:"ADD_ENDPOINT" Seq=34 Len=17] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=2] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=2] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=2:"ADD_ENDPOINT" Seq=34 Len=6] [2024-05-04 20:28:47] debug: zh:ember: Registered endpoint "242" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=35 Len=10] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=3] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=3] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=35 Len=6] [2024-05-04 20:28:47] debug: zh:ember: Registered multicast table entry: {"multicastId":2948,"endpoint":242,"networkIndex":0}. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=36 Len=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=4] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=4] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=36 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspPolicyId] SET "TC_KEY_REQUEST_POLICY" TO "81" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=37 Len=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=5] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=37 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspPolicyId] SET "APP_KEY_REQUEST_POLICY" TO "96" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=38 Len=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=38 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [EzspPolicyId] SET "TRUST_CENTER_POLICY" TO "3" with status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=23:"NETWORK_INIT" Seq=39 Len=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=7] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=7] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=23:"NETWORK_INIT" Seq=39 Len=6] [2024-05-04 20:28:47] debug: zh:ember: [INIT TC] Network init status=SUCCESS. [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=0] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=25:"STACK_STATUS_HANDLER" Seq=39 Len=6] [2024-05-04 20:28:47] debug: zh:ember:ezsp: ezspStackStatusHandler(): callback called with: [status=NETWORK_UP] [2024-05-04 20:28:47] info: zh:ember: [STACK STATUS] Network up. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=40:"GET_NETWORK_PARAMETERS" Seq=40 Len=5] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=1] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=1] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=40:"GET_NETWORK_PARAMETERS" Seq=40 Len=27] [2024-05-04 20:28:47] debug: zh:ember: [INIT TC] Current network config={"networkKeyDistribute":false,"networkKey":[49,5,217,11,55,130,46,153,234,181,181,103,180,130,229,235],"panID":6759,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[17]} [2024-05-04 20:28:47] debug: zh:ember: [INIT TC] Current NCP network: nodeType=COORDINATOR params={"extendedPanId":[221,221,221,221,221,221,221,221],"panId":6759,"radioTxPower":5,"radioChannel":17,"joinMethod":0,"nwkManagerId":0,"nwkUpdateId":0,"channels":134215680} [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=276:"EXPORT_KEY" Seq=41 Len=23] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=2] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=2] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=276:"EXPORT_KEY" Seq=41 Len=25] [2024-05-04 20:28:47] debug: zh:ember: [INIT TC] Current NCP network: networkKey=3105d90b37822e99eab5b567b482e5eb [2024-05-04 20:28:47] info: zh:ember: [INIT TC] NCP network matches config. [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=16:"SET_CONCENTRATOR" Seq=42 Len=15] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=3] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=3] Added to rxQueue [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-05-04 20:28:47] debug: zh:ember:ezsp: <=== [FRAME: ID=16:"SET_CONCENTRATOR" Seq=42 Len=6] [2024-05-04 20:28:47] debug: zh:ember:ezsp: ===> [FRAME: ID=90:"SET_SOURCE_ROUTE_DISCOVERY_MODE" Seq=43 Len=6] [2024-05-04 20:28:47] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=4] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=4] Added to rxQueue [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-05-04 20:28:48] debug: zh:ember:ezsp: <=== [FRAME: ID=90:"SET_SOURCE_ROUTE_DISCOVERY_MODE" Seq=43 Len=9] [2024-05-04 20:28:48] info: zh:ember: [CONCENTRATOR] Started source route discovery. 1248ms until next broadcast. [2024-05-04 20:28:48] debug: zh:ember:ezsp: ===> [FRAME: ID=40:"GET_NETWORK_PARAMETERS" Seq=44 Len=5] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=5] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=5] Added to rxQueue [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-05-04 20:28:48] debug: zh:ember:ezsp: <=== [FRAME: ID=40:"GET_NETWORK_PARAMETERS" Seq=44 Len=27] [2024-05-04 20:28:48] debug: zh:ember:ezsp: ===> [FRAME: ID=24:"NETWORK_STATE" Seq=45 Len=5] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=6] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=6] Added to rxQueue [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-05-04 20:28:48] debug: zh:ember:ezsp: <=== [FRAME: ID=24:"NETWORK_STATE" Seq=45 Len=6] [2024-05-04 20:28:48] debug: zh:ember:ezsp: ===> [FRAME: ID=38:"GET_EUI64" Seq=46 Len=5] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=7] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=7] Added to rxQueue [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-05-04 20:28:48] debug: zh:ember:ezsp: <=== [FRAME: ID=38:"GET_EUI64" Seq=46 Len=13] [2024-05-04 20:28:48] debug: zh:ember: [INIT] Network Ready! {"eui64":"0x6c5cb1fffefc7516","parameters":{"extendedPanId":[221,221,221,221,221,221,221,221],"panId":6759,"radioTxPower":5,"radioChannel":17,"joinMethod":0,"nwkManagerId":0,"nwkUpdateId":0,"channels":134215680},"status":2} [2024-05-04 20:28:48] debug: zh:ember:queue: Dispatching started. [2024-05-04 20:28:48] debug: zh:controller: Started with result 'resumed' [2024-05-04 20:28:48] debug: zh:ember:queue: Status queue=0 priorityQueue=0. [2024-05-04 20:28:48] debug: zh:controller: Injected database: true, adapter: true [2024-05-04 20:28:48] debug: zh:ember:queue: Status queue=0 priorityQueue=0. [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0x6c5cb1fffefc7516): default expiration timeout set to 0 [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0x842e14fffe64df47): default expiration timeout set to 0 [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0xa4c13800aa1009ca): default expiration timeout set to 0 [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0xa4c13800aa402e54): default expiration timeout set to 0 [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0x588e81fffed3a284): default expiration timeout set to 0 [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0xec1bbdfffe9a3fa8): default expiration timeout set to 43200000 [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0x0017880106f46463): default expiration timeout set to 0 [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0xa4c138d8a813aaa9): default expiration timeout set to 0 [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0x00124b0022cd1922): default expiration timeout set to 0 [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0x60a423fffec77618): default expiration timeout set to 0 [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0x00124b0025135376): default expiration timeout set to 0 [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0x7cb03eaa00b24882): default expiration timeout set to 0 [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0xa4c13874fb41ee57): default expiration timeout set to 0 [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0x84ba20fffe762920): default expiration timeout set to 43200000 [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0x588e81fffed39555): default expiration timeout set to 0 [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0x588e81fffed39369): default expiration timeout set to 0 [2024-05-04 20:28:48] debug: zh:controller:device: Request Queue (0x00158d00038931ac): default expiration timeout set to 0 [2024-05-04 20:28:48] info: z2m: zigbee-herdsman started (resumed) [2024-05-04 20:28:48] 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"}' [2024-05-04 20:28:48] debug: z2m: Zigbee network parameters: {"channel":17,"extendedPanID":15987178197214945000,"panID":6759} [2024-05-04 20:28:48] info: z2m: Currently 16 devices are joined: [2024-05-04 20:28:48] info: z2m: FloorLamp (0x842e14fffe64df47): E1603/E1702/E1708 - IKEA TRADFRI control outlet (Router) [2024-05-04 20:28:48] info: z2m: KitchenMainLight (0xa4c13800aa1009ca): 404036/45327/45317/45328 - MΓΌller Licht Tint LED white+color (Router) [2024-05-04 20:28:48] info: z2m: LivingRoomMain (0xa4c13800aa402e54): 404036/45327/45317/45328 - MΓΌller Licht Tint LED white+color (Router) [2024-05-04 20:28:48] info: z2m: ComputerPower (0x588e81fffed3a284): TS0121_plug - TuYa 10A UK or 16A EU smart plug (Router) [2024-05-04 20:28:48] info: z2m: LivingRoomSwitch (0xec1bbdfffe9a3fa8): E1524/E1810 - IKEA TRADFRI remote control (EndDevice) [2024-05-04 20:28:48] info: z2m: KitchenMotion (0x0017880106f46463): 9290012607 - Philips Hue motion sensor (EndDevice) [2024-05-04 20:28:48] info: z2m: LetterBox (0xa4c138d8a813aaa9): IH012-RT01 - TuYa Motion sensor (EndDevice) [2024-05-04 20:28:48] info: z2m: 0x00124b0022cd1922 (0x00124b0022cd1922): SNZB-03 - SONOFF Motion sensor (EndDevice) [2024-05-04 20:28:48] info: z2m: KitchenSubLight (0x60a423fffec77618): 404031 - MΓΌller Licht Tint Armaro (Router) [2024-05-04 20:28:48] info: z2m: RefrigeratorDoor (0x00124b0025135376): SNZB-04 - SONOFF Contact sensor (EndDevice) [2024-05-04 20:28:48] info: z2m: MeanderLamp (0x7cb03eaa00b24882): AB3257001NJ - OSRAM Smart+ plug (Router) [2024-05-04 20:28:48] info: z2m: 0xa4c13874fb41ee57 (0xa4c13874fb41ee57): TS0601_smart_air_house_keeper - TuYa Smart air house keeper (Router) [2024-05-04 20:28:48] info: z2m: PresenceButton (0x84ba20fffe762920): E1812 - IKEA TRADFRI shortcut button (EndDevice) [2024-05-04 20:28:48] info: z2m: PlaystationPower (0x588e81fffed39555): TS0121_plug - TuYa 10A UK or 16A EU smart plug (Router) [2024-05-04 20:28:48] info: z2m: AmbilightPower (0x588e81fffed39369): TS0121_plug - TuYa 10A UK or 16A EU smart plug (Router) [2024-05-04 20:28:48] info: z2m: TVPower (0x00158d00038931ac): SP 120 - Innr Smart plug (Router) [2024-05-04 20:28:48] info: z2m: Zigbee: disabling joining new devices. [2024-05-04 20:28:48] debug: zh:controller: Disable joining [2024-05-04 20:28:48] debug: zh:ember:queue: Status queue=0 priorityQueue=0. [2024-05-04 20:28:48] debug: zh:ember: ~~~> [ZCL BROADCAST apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":4416,"groupId":65533,"sequence":0} header={"frameControl":{"reservedBits":0,"frameType":1,"direction":1,"disableDefaultResponse":true,"manufacturerSpecific":false},"manufacturerCode":null,"transactionSequenceNumber":2,"commandIdentifier":2}] [2024-05-04 20:28:48] debug: zh:ember:ezsp: ===> [FRAME: ID=54:"SEND_BROADCAST" Seq=47 Len=27] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=0] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=0] Added to rxQueue [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-05-04 20:28:48] debug: zh:ember:ezsp: <=== [FRAME: ID=54:"SEND_BROADCAST" Seq=47 Len=7] [2024-05-04 20:28:48] debug: zh:ember:ezsp: ~~~> [SENT type=BROADCAST apsSequence=82 messageTag=1 status=SUCCESS] [2024-05-04 20:28:48] debug: zh:ember:queue: Status queue=0 priorityQueue=0. [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=1] Added to rxQueue [2024-05-04 20:28:48] debug: zh:ember:ezsp: ===> [FRAME: ID=107:"CLEAR_TRANSIENT_LINK_KEYS" Seq=48 Len=5] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=0 frmRx=2] [2024-05-04 20:28:48] debug: zh:ember:ezsp: Skipping async callback while waiting for response to command. [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1 frmNum=2] Added to rxQueue [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-05-04 20:28:48] debug: zh:ember:ezsp: Skipping async callback while waiting for response to command. [2024-05-04 20:28:48] debug: zh:ember:ezsp: <=== [FRAME: ID=107:"CLEAR_TRANSIENT_LINK_KEYS" Seq=48 Len=5] [2024-05-04 20:28:48] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=49 Len=7] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=1 frmRx=3] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2 frmNum=3] Added to rxQueue [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-05-04 20:28:48] debug: zh:ember:ezsp: Skipping async callback while waiting for response to command. [2024-05-04 20:28:48] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=49 Len=6] [2024-05-04 20:28:48] debug: zh:ember: [EzspPolicyId] SET "TRUST_CENTER_POLICY" TO "2" with status=SUCCESS. [2024-05-04 20:28:48] debug: zh:ember:ezsp: ===> [FRAME: ID=34:"PERMIT_JOINING" Seq=50 Len=6] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=2 frmRx=4] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3 frmNum=4] Added to rxQueue [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-05-04 20:28:48] debug: zh:ember:ezsp: Skipping async callback while waiting for response to command. [2024-05-04 20:28:48] debug: zh:ember:ezsp: <=== [FRAME: ID=34:"PERMIT_JOINING" Seq=50 Len=6] [2024-05-04 20:28:48] debug: zh:ember: Permit joining for 0 sec. status=0 [2024-05-04 20:28:48] debug: zh:ember: ~~~> [ZDO PERMIT_JOINING_REQUEST target=65532 duration=0 authentication=1] [2024-05-04 20:28:48] debug: zh:ember: ~~~> [ZDO BROADCAST apsFrame={"profileId":0,"clusterId":54,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":0} messageTag=1] [2024-05-04 20:28:48] debug: zh:ember:ezsp: ===> [FRAME: ID=54:"SEND_BROADCAST" Seq=51 Len=24] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=3 frmRx=5] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=5] Added to rxQueue [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-05-04 20:28:48] debug: zh:ember:ezsp: Skipping async callback while waiting for response to command. [2024-05-04 20:28:48] debug: zh:ember:ezsp: <=== [FRAME: ID=54:"SEND_BROADCAST" Seq=51 Len=7] [2024-05-04 20:28:48] debug: zh:ember: ~~~> [SENT ZDO type=BROADCAST apsFrame={"profileId":0,"clusterId":54,"sourceEndpoint":0,"destinationEndpoint":0,"options":4416,"groupId":0,"sequence":83} messageTag=1 status=SUCCESS] [2024-05-04 20:28:48] info: z2m: Connecting to MQTT server at mqtt://localhost:1883 [2024-05-04 20:28:48] debug: z2m: Using MQTT keepalive: 60 [2024-05-04 20:28:48] debug: z2m: Using MQTT login with username: openhabian [2024-05-04 20:28:48] debug: z2m: Using MQTT client ID: 'Zigbee' [2024-05-04 20:28:48] debug: zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=47 Len=30] [2024-05-04 20:28:48] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=BROADCAST_LOOPBACK], [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":82}], [lastHopLqi=255], [lastHopRssi=0], [sender=0], [bindingIndex=255], [addressIndex=255], [messageContents=1902020a0000] [2024-05-04 20:28:48] info: z2m: Connected to MQTT server [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: Active device 'FloorLamp' was last seen '10.00' minutes ago. [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/FloorLamp/availability', payload '{"state":"offline"}' [2024-05-04 20:28:48] debug: zh:controller:endpoint: ZCL command 0x842e14fffe64df47/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) [2024-05-04 20:28:48] debug: zh:ember:queue: Status queue=0 priorityQueue=0. [2024-05-04 20:28:48] debug: z2m: Active device 'KitchenMainLight' was last seen '51.07' minutes ago. [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/KitchenMainLight/availability', payload '{"state":"offline"}' [2024-05-04 20:28:48] debug: z2m: Active device 'LivingRoomMain' was last seen '1.72' minutes ago. [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/LivingRoomMain/availability', payload '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: Active device 'ComputerPower' was last seen '0.84' minutes ago. [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/ComputerPower/availability', payload '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: Passive device 'LivingRoomSwitch' was last seen '7.28' hours ago. [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/LivingRoomSwitch/availability', payload '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: Passive device 'KitchenMotion' was last seen '0.25' hours ago. [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/KitchenMotion/availability', payload '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: Passive device 'LetterBox' was last seen '2.38' hours ago. [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/LetterBox/availability', payload '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: Passive device '0x00124b0022cd1922' was last seen '1.24' hours ago. [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/0x00124b0022cd1922/availability', payload '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: Active device 'KitchenSubLight' was last seen '41.68' minutes ago. [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/KitchenSubLight/availability', payload '{"state":"offline"}' [2024-05-04 20:28:48] debug: z2m: Passive device 'RefrigeratorDoor' was last seen '0.37' hours ago. [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/RefrigeratorDoor/availability', payload '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: Active device 'MeanderLamp' was last seen '1.66' minutes ago. [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/MeanderLamp/availability', payload '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: Active device '0xa4c13874fb41ee57' was last seen '125351.62' minutes ago. [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/0xa4c13874fb41ee57/availability', payload '{"state":"offline"}' [2024-05-04 20:28:48] debug: z2m: Passive device 'PresenceButton' was last seen '2.42' hours ago. [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/PresenceButton/availability', payload '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: Active device 'PlaystationPower' was last seen '0.84' minutes ago. [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/PlaystationPower/availability', payload '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: Active device 'AmbilightPower' was last seen '0.84' minutes ago. [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/AmbilightPower/availability', payload '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: Active device 'TVPower' was last seen '1.70' minutes ago. [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/TVPower/availability', payload '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/1/availability', payload '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/901/availability', payload '{"state":"online"}' [2024-05-04 20:28:48] info: z2m: Started frontend on port 8085 [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/FloorLamp', payload '{"device":{"applicationVersion":32,"dateCode":"20211118","friendlyName":"FloorLamp","hardwareVersion":1,"ieeeAddr":"0x842e14fffe64df47","manufacturerID":4476,"manufacturerName":"IKEA of Sweden","model":"E1603/E1702/E1708","networkAddress":49820,"powerSource":"Mains (single phase)","softwareBuildID":"2.3.089","stackVersion":98,"type":"Router","zclVersion":3},"last_seen":"2024-05-04T20:18:48+02:00","linkquality":196,"power_on_behavior":"previous","state":"OFF","update":{"installed_version":587765297,"latest_version":587765297,"state":"idle"},"update_available":false}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/KitchenMainLight', payload '{"brightness":254,"color":{"x":null,"y":null},"color_mode":"xy","color_temp":null,"device":{"applicationVersion":0,"friendlyName":"KitchenMainLight","hardwareVersion":0,"ieeeAddr":"0xa4c13800aa1009ca","manufacturerID":4635,"manufacturerName":"MLI","model":"404036/45327/45317/45328","networkAddress":5149,"powerSource":"Mains (single phase)","softwareBuildID":"MPANL501","stackVersion":2,"type":"Router","zclVersion":3},"last_seen":"2024-05-04T19:37:44+02:00","linkquality":200,"state":"OFF"}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/LivingRoomMain', payload '{"brightness":94,"color":{"x":0.349,"y":0.327},"color_mode":"xy","device":{"applicationVersion":0,"friendlyName":"LivingRoomMain","hardwareVersion":0,"ieeeAddr":"0xa4c13800aa402e54","manufacturerID":4635,"manufacturerName":"MLI","model":"404036/45327/45317/45328","networkAddress":44588,"powerSource":"Mains (single phase)","softwareBuildID":"MPANL501","stackVersion":2,"type":"Router","zclVersion":3},"last_seen":"2024-05-04T20:27:05+02:00","linkquality":204,"state":"ON"}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/ComputerPower', payload '{"current":0.38,"device":{"applicationVersion":65,"dateCode":"","friendlyName":"ComputerPower","hardwareVersion":1,"ieeeAddr":"0x588e81fffed3a284","manufacturerID":4098,"manufacturerName":"_TZ3000_g5xawfcq","model":"TS0121_plug","networkAddress":55839,"powerSource":"Mains (single phase)","stackVersion":0,"type":"Router","zclVersion":3},"energy":137.46,"indicator_mode":"off/on","last_seen":"2024-05-04T20:27:58+02:00","linkquality":204,"power":105,"power_outage_memory":"restore","state":"ON","voltage":234}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/LivingRoomSwitch', payload '{"battery":30,"device":{"applicationVersion":33,"dateCode":"20190401","friendlyName":"LivingRoomSwitch","hardwareVersion":1,"ieeeAddr":"0xec1bbdfffe9a3fa8","manufacturerID":4476,"manufacturerName":"IKEA of Sweden","model":"E1524/E1810","networkAddress":17936,"powerSource":"Battery","softwareBuildID":"24.4.5","stackVersion":98,"type":"EndDevice","zclVersion":3},"last_seen":"2024-05-04T13:12:04+02:00","linkquality":87,"update":{"installed_version":604241925,"latest_version":604241925,"state":"idle"},"update_available":false}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/KitchenMotion', payload '{"battery":81.5,"device":{"applicationVersion":2,"dateCode":"20190219","friendlyName":"KitchenMotion","hardwareVersion":1,"ieeeAddr":"0x0017880106f46463","manufacturerID":4107,"manufacturerName":"Philips","model":"9290012607","networkAddress":39254,"powerSource":"Battery","softwareBuildID":"6.1.1.27575","stackVersion":1,"type":"EndDevice","zclVersion":1},"illuminance":0,"illuminance_lux":0,"last_seen":"2024-05-04T20:13:43+02:00","linkquality":255,"occupancy":false,"occupancy_timeout":0,"temperature":17.9,"update":{"installed_version":1107323831,"latest_version":1107323831,"state":"idle"}}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/LetterBox', payload '{"battery":100,"battery_low":false,"device":{"applicationVersion":70,"dateCode":"","friendlyName":"LetterBox","hardwareVersion":1,"ieeeAddr":"0xa4c138d8a813aaa9","manufacturerID":4417,"manufacturerName":"_TZ3000_6ygjfyll","model":"IH012-RT01","networkAddress":40158,"powerSource":"Battery","stackVersion":0,"type":"EndDevice","zclVersion":3},"keep_time":30,"last_seen":"2024-05-04T18:05:48+02:00","linkquality":196,"occupancy":false,"sensitivity":"medium","tamper":false,"voltage":2900}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/0x00124b0022cd1922', payload '{"battery":64,"battery_low":false,"device":{"applicationVersion":4,"dateCode":"20201026","friendlyName":"0x00124b0022cd1922","hardwareVersion":1,"ieeeAddr":"0x00124b0022cd1922","manufacturerID":0,"manufacturerName":"eWeLink","model":"SNZB-03","networkAddress":64152,"powerSource":"Battery","type":"EndDevice","zclVersion":1},"last_seen":"2024-05-04T19:14:11+02:00","linkquality":204,"occupancy":false,"tamper":false,"voltage":2900}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/KitchenSubLight', payload '{"brightness":254,"color_mode":"color_temp","color_temp":370,"device":{"applicationVersion":40,"dateCode":"NULL","friendlyName":"KitchenSubLight","hardwareVersion":0,"ieeeAddr":"0x60a423fffec77618","manufacturerID":4635,"manufacturerName":"MLI","model":"404031","networkAddress":59242,"powerSource":"Mains (single phase)","softwareBuildID":"2.5.3_r47","stackVersion":0,"type":"Router","zclVersion":3},"last_seen":"2024-05-04T19:47:07+02:00","linkquality":200,"state":"OFF"}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/RefrigeratorDoor', payload '{"battery":100,"battery_low":false,"contact":true,"device":{"applicationVersion":5,"dateCode":"20211103","friendlyName":"RefrigeratorDoor","hardwareVersion":1,"ieeeAddr":"0x00124b0025135376","manufacturerID":0,"manufacturerName":"eWeLink","model":"SNZB-04","networkAddress":59790,"powerSource":"Battery","type":"EndDevice","zclVersion":1},"last_seen":"2024-05-04T20:06:23+02:00","linkquality":188,"tamper":false,"voltage":3000}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/MeanderLamp', payload '{"device":{"applicationVersion":17,"dateCode":"20140331DEOS****","friendlyName":"MeanderLamp","hardwareVersion":1,"ieeeAddr":"0x7cb03eaa00b24882","manufacturerID":48042,"manufacturerName":"OSRAM","model":"AB3257001NJ","networkAddress":26147,"powerSource":"Mains (single phase)","softwareBuildID":"V1.05.11","stackVersion":2,"type":"Router","zclVersion":1},"last_seen":"2024-05-04T20:27:08+02:00","linkquality":144,"state":"OFF","update":{"installed_version":16909585,"latest_version":16909577,"state":"idle"},"update_available":false}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/0xa4c13874fb41ee57', payload '{"co2":365,"device":{"applicationVersion":70,"dateCode":"","friendlyName":"0xa4c13874fb41ee57","hardwareVersion":1,"ieeeAddr":"0xa4c13874fb41ee57","manufacturerID":4417,"manufacturerName":"_TZE200_dwcarsat","model":"TS0601_smart_air_house_keeper","networkAddress":44858,"powerSource":"Mains (single phase)","stackVersion":0,"type":"Router","zclVersion":3},"formaldehyd":3,"humidity":51.2,"last_seen":"2024-02-07T18:17:11+01:00","linkquality":61,"pm25":3,"temperature":19.9,"voc":11}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/PresenceButton', payload '{"battery":87,"device":{"applicationVersion":33,"dateCode":"20210727","friendlyName":"PresenceButton","hardwareVersion":1,"ieeeAddr":"0x84ba20fffe762920","manufacturerID":4476,"manufacturerName":"IKEA of Sweden","model":"E1812","networkAddress":31868,"powerSource":"Battery","softwareBuildID":"2.3.080","stackVersion":98,"type":"EndDevice","zclVersion":3},"last_seen":"2024-05-04T18:03:41+02:00","linkquality":180,"update":{"installed_version":587728433,"latest_version":604241926,"state":"available"},"update_available":true}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/PlaystationPower', payload '{"current":0,"device":{"applicationVersion":65,"dateCode":"","friendlyName":"PlaystationPower","hardwareVersion":1,"ieeeAddr":"0x588e81fffed39555","manufacturerID":4098,"manufacturerName":"_TZ3000_g5xawfcq","model":"TS0121_plug","networkAddress":53528,"powerSource":"Mains (single phase)","stackVersion":0,"type":"Router","zclVersion":3},"energy":34.54,"indicator_mode":"off/on","last_seen":"2024-05-04T20:27:58+02:00","linkquality":196,"power":0,"power_outage_memory":"restore","state":"OFF","voltage":234}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/AmbilightPower', payload '{"current":0,"device":{"applicationVersion":65,"dateCode":"","friendlyName":"AmbilightPower","hardwareVersion":1,"ieeeAddr":"0x588e81fffed39369","manufacturerID":4098,"manufacturerName":"_TZ3000_g5xawfcq","model":"TS0121_plug","networkAddress":37887,"powerSource":"Mains (single phase)","stackVersion":0,"type":"Router","zclVersion":3},"energy":6.5,"indicator_mode":"off/on","last_seen":"2024-05-04T20:27:57+02:00","linkquality":208,"power":0,"power_outage_memory":"restore","state":"OFF","voltage":234}' [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/TVPower', payload '{"current":0.12,"device":{"applicationVersion":1,"dateCode":"20171027-100","friendlyName":"TVPower","hardwareVersion":1,"ieeeAddr":"0x00158d00038931ac","manufacturerID":4454,"manufacturerName":"innr","model":"SP 120","networkAddress":64756,"powerSource":"Mains (single phase)","softwareBuildID":"2.0","stackVersion":2,"type":"Router","zclVersion":2},"energy":0.44,"last_seen":"2024-05-04T20:27:06+02:00","linkquality":196,"power":20,"state":"ON","voltage":233}' [2024-05-04 20:28:48] info: z2m: Zigbee2MQTT started! [2024-05-04 20:28:48] debug: zh:ember: ~~~> [ZCL to=49820 apsFrame={"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":0} header={"frameControl":{"reservedBits":0,"frameType":0,"direction":0,"disableDefaultResponse":true,"manufacturerSpecific":false},"manufacturerCode":null,"transactionSequenceNumber":3,"commandIdentifier":0}] [2024-05-04 20:28:48] debug: zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=52 Len=26] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=4 frmRx=6] [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/bridge/config' with data '{"commit":"fe0742a","coordinator":{"meta":{"maintrel":1,"majorrel":2,"minorrel":7,"product":1,"revision":20230507,"transportrev":2},"type":"zStack3x0"},"log_level":"info","network":{"channel":17,"extendedPanID":"0xdddddddddddddddd","panID":6759},"permit_join":false,"version":"1.35.3"}' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/WarehouseLight/availability' with data 'online' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/DrainTest/availability' with data 'offline' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/KitchenSinkLight/availability' with data 'offline' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/MilkWarmer/availability' with data 'offline' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/KitchenSwitch/availability' with data 'offline' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/BedroomSwitch/availability' with data 'offline' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/BedroomLight/availability' with data 'offline' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/LivingRoomCouchRight/availability' with data 'offline' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/LivingRoomCouchLeft/availability' with data 'offline' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/KitchenLight/availability' with data 'offline' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/TintRemote/availability' with data 'online' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/tint/availability' with data 'online' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/PrinterPower/availability' with data 'offline' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/KitchenMotionBkp/availability' with data 'online' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/0x84ba20fffe671f10/availability' with data 'online' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/NotUsedMotion/availability' with data 'offline' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/0x9035eafffec88ad9/availability' with data 'online' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/test_lights/availability' with data 'online' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/Coordinator/availability' with data '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/0x7cb03eaa0a02b79e/availability' with data '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: Received MQTT message on 'zigbee2mqtt/Smokey/availability' with data 'online' [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=6] Added to rxQueue [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-05-04 20:28:48] debug: zh:ember:ezsp: <=== [FRAME: ID=52:"SEND_UNICAST" Seq=52 Len=7] [2024-05-04 20:28:48] debug: zh:ember:ezsp: ~~~> [SENT type=DIRECT apsSequence=84 messageTag=2 status=SUCCESS] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=7] Added to rxQueue [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-05-04 20:28:48] debug: zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=52 Len=32] [2024-05-04 20:28:48] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":181}], [lastHopLqi=208], [lastHopRssi=208], [sender=49820], [bindingIndex=255], [addressIndex=255], [messageContents=1803010000002003] [2024-05-04 20:28:48] debug: zh:controller: Received payload: clusterID=0, address=49820, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=208, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":3,"commandIdentifier":1},"payload":[{"attrId":0,"status":0,"dataType":32,"attrData":3}],"command":{"ID":1,"name":"readRsp","parameters":[{"name":"attrId","type":33},{"name":"status","type":32},{"name":"dataType","type":32,"conditions":[{"type":"statusEquals","value":0}]},{"name":"attrData","type":1000,"conditions":[{"type":"statusEquals","value":0}]}]}} [2024-05-04 20:28:48] debug: z2m: Device 'FloorLamp' reconnected [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/FloorLamp/availability', payload '{"state":"online"}' [2024-05-04 20:28:48] debug: z2m: Received Zigbee message from 'FloorLamp', type 'readResponse', cluster 'genBasic', data '{"zclVersion":3}' from endpoint 1 with groupID 0 [2024-05-04 20:28:48] debug: z2m: MQTT publish: topic 'zigbee2mqtt/FloorLamp', payload '{"device":{"applicationVersion":32,"dateCode":"20211118","friendlyName":"FloorLamp","hardwareVersion":1,"ieeeAddr":"0x842e14fffe64df47","manufacturerID":4476,"manufacturerName":"IKEA of Sweden","model":"E1603/E1702/E1708","networkAddress":49820,"powerSource":"Mains (single phase)","softwareBuildID":"2.3.089","stackVersion":98,"type":"Router","zclVersion":3},"last_seen":"2024-05-04T20:28:48+02:00","linkquality":208,"power_on_behavior":"previous","state":"OFF","update":{"installed_version":587765297,"latest_version":587765297,"state":"idle"},"update_available":false}' [2024-05-04 20:28:48] debug: z2m: Successfully pinged 'FloorLamp' (attempt 1/1) [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-05-04 20:28:48] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=0] Added to rxQueue [2024-05-04 20:28:48] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-05-04 20:28:48] debug: zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=52 Len=27] [2024-05-04 20:28:48] debug: zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=DIRECT], [indexOrDestination=49820], [apsFrame={"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":84}], [messageTag=2], [status=SUCCESS], [messageContents=1003000000] [2024-05-04 20:28:49] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:49] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-05-04 20:28:49] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=1] Added to rxQueue [2024-05-04 20:28:49] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-05-04 20:28:49] debug: zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=52 Len=28] [2024-05-04 20:28:49] debug: zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=BROADCAST], [indexOrDestination=65533], [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":82}], [messageTag=255], [status=SUCCESS], [messageContents=1902020a0000] [2024-05-04 20:28:49] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:49] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5] [2024-05-04 20:28:49] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5 frmNum=2] Added to rxQueue [2024-05-04 20:28:49] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-05-04 20:28:49] debug: zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=52 Len=25] [2024-05-04 20:28:49] debug: zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=BROADCAST], [indexOrDestination=65532], [apsFrame={"profileId":0,"clusterId":54,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":83}], [messageTag=1], [status=SUCCESS], [messageContents=010001] [2024-05-04 20:28:50] debug: z2m: Retrieving state of 'FloorLamp' after reconnect [2024-05-04 20:28:50] debug: zh:controller:endpoint: ZCL command 0x842e14fffe64df47/1 genOnOff.read(["onOff"], {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) [2024-05-04 20:28:50] debug: zh:ember:queue: Status queue=0 priorityQueue=0. [2024-05-04 20:28:50] debug: zh:ember: ~~~> [ZCL to=49820 apsFrame={"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":0} header={"frameControl":{"reservedBits":0,"frameType":0,"direction":0,"disableDefaultResponse":true,"manufacturerSpecific":false},"manufacturerCode":null,"transactionSequenceNumber":4,"commandIdentifier":0}] [2024-05-04 20:28:50] debug: zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=53 Len=26] [2024-05-04 20:28:50] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=5 frmRx=3] [2024-05-04 20:28:50] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:50] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-05-04 20:28:50] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=3] Added to rxQueue [2024-05-04 20:28:50] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-05-04 20:28:50] debug: zh:ember:ezsp: <=== [FRAME: ID=52:"SEND_UNICAST" Seq=53 Len=7] [2024-05-04 20:28:50] debug: zh:ember:ezsp: ~~~> [SENT type=DIRECT apsSequence=85 messageTag=3 status=SUCCESS] [2024-05-04 20:28:50] debug: zh:controller:endpoint: ZCL command 0xa4c13800aa1009ca/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) [2024-05-04 20:28:50] debug: zh:ember:queue: Status queue=1 priorityQueue=0. [2024-05-04 20:28:50] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:50] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-05-04 20:28:50] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=4] Added to rxQueue [2024-05-04 20:28:50] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=5] [2024-05-04 20:28:50] debug: zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=53 Len=32] [2024-05-04 20:28:50] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":320,"groupId":0,"sequence":182}], [lastHopLqi=208], [lastHopRssi=208], [sender=49820], [bindingIndex=255], [addressIndex=255], [messageContents=1804010000001000] [2024-05-04 20:28:50] debug: zh:controller: Received payload: clusterID=6, address=49820, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=208, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":true,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":4,"commandIdentifier":1},"payload":[{"attrId":0,"status":0,"dataType":16,"attrData":0}],"command":{"ID":1,"name":"readRsp","parameters":[{"name":"attrId","type":33},{"name":"status","type":32},{"name":"dataType","type":32,"conditions":[{"type":"statusEquals","value":0}]},{"name":"attrData","type":1000,"conditions":[{"type":"statusEquals","value":0}]}]}} [2024-05-04 20:28:50] debug: z2m: Received Zigbee message from 'FloorLamp', type 'readResponse', cluster 'genOnOff', data '{"onOff":0}' from endpoint 1 with groupID 0 [2024-05-04 20:28:50] debug: z2m: MQTT publish: topic 'zigbee2mqtt/FloorLamp', payload '{"device":{"applicationVersion":32,"dateCode":"20211118","friendlyName":"FloorLamp","hardwareVersion":1,"ieeeAddr":"0x842e14fffe64df47","manufacturerID":4476,"manufacturerName":"IKEA of Sweden","model":"E1603/E1702/E1708","networkAddress":49820,"powerSource":"Mains (single phase)","softwareBuildID":"2.3.089","stackVersion":98,"type":"Router","zclVersion":3},"last_seen":"2024-05-04T20:28:50+02:00","linkquality":208,"power_on_behavior":"previous","state":"OFF","update":{"installed_version":587765297,"latest_version":587765297,"state":"idle"},"update_available":false}' [2024-05-04 20:28:50] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:50] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6] [2024-05-04 20:28:50] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6 frmNum=5] Added to rxQueue [2024-05-04 20:28:50] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6] [2024-05-04 20:28:50] debug: zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=53 Len=27] [2024-05-04 20:28:50] debug: zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=DIRECT], [indexOrDestination=49820], [apsFrame={"profileId":260,"clusterId":6,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":85}], [messageTag=3], [status=SUCCESS], [messageContents=1004000000] [2024-05-04 20:28:50] debug: zh:ember: ~~~> [ZCL to=5149 apsFrame={"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4416,"groupId":0,"sequence":0} header={"frameControl":{"reservedBits":0,"frameType":0,"direction":0,"disableDefaultResponse":true,"manufacturerSpecific":false},"manufacturerCode":null,"transactionSequenceNumber":5,"commandIdentifier":0}] [2024-05-04 20:28:50] debug: zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=54 Len=26] [2024-05-04 20:28:50] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=6 frmRx=6] [2024-05-04 20:28:50] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:50] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-05-04 20:28:50] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=6] Added to rxQueue [2024-05-04 20:28:50] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=7] [2024-05-04 20:28:50] debug: zh:ember:ezsp: <=== [FRAME: ID=52:"SEND_UNICAST" Seq=54 Len=7] [2024-05-04 20:28:50] debug: zh:ember:ezsp: ~~~> [SENT type=DIRECT apsSequence=86 messageTag=4 status=SUCCESS] [2024-05-04 20:28:55] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:55] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-05-04 20:28:55] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=7] Added to rxQueue [2024-05-04 20:28:55] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=0] [2024-05-04 20:28:55] debug: zh:ember:ezsp: <=== [FRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=54 Len=27] [2024-05-04 20:28:55] debug: zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [type=DIRECT], [indexOrDestination=5149], [apsFrame={"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":86}], [messageTag=4], [status=DELIVERY_FAILED], [messageContents=1005000000] [2024-05-04 20:28:55] debug: zh:controller:endpoint: ZCL command 0xa4c13800aa1009ca/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":86}) [2024-05-04 20:28:55] warning: z2m: Failed to ping 'KitchenMainLight' (attempt 1/1, ZCL command 0xa4c13800aa1009ca/1 genBasic.read(["zclVersion"], {"timeout":10000,"disableResponse":false,"disableRecovery":true,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":null,"writeUndiv":false}) failed (Delivery failed for {"profileId":260,"clusterId":0,"sourceEndpoint":1,"destinationEndpoint":1,"options":4160,"groupId":0,"sequence":86})) [2024-05-04 20:28:57] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:57] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7] [2024-05-04 20:28:57] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7 frmNum=0] Added to rxQueue [2024-05-04 20:28:57] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=1] [2024-05-04 20:28:57] debug: zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=54 Len=36] [2024-05-04 20:28:57] debug: zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":1794,"sourceEndpoint":1,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":61}], [lastHopLqi=208], [lastHopRssi=208], [sender=53528], [bindingIndex=255], [addressIndex=255], [messageContents=08100a0000257e0d00000000] [2024-05-04 20:28:57] debug: zh:controller: Received payload: clusterID=1794, address=53528, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=208, frame={"header":{"frameControl":{"frameType":0,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":false,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":16,"commandIdentifier":10},"payload":[{"attrId":0,"dataType":37,"attrData":[0,3454]}],"command":{"ID":10,"name":"report","parameters":[{"name":"attrId","type":33},{"name":"dataType","type":32},{"name":"attrData","type":1000}]}} [2024-05-04 20:28:57] debug: zh:controller:endpoint: ZCL command 0x588e81fffed39555/1 seMetering.defaultRsp({"cmdId":10,"statusCode":0}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":1,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":16,"writeUndiv":false}) [2024-05-04 20:28:57] debug: zh:ember:queue: Status queue=0 priorityQueue=0. [2024-05-04 20:28:57] debug: z2m: Received Zigbee message from 'PlaystationPower', type 'attributeReport', cluster 'seMetering', data '{"currentSummDelivered":[0,3454]}' from endpoint 1 with groupID 0 [2024-05-04 20:28:57] debug: z2m: MQTT publish: topic 'zigbee2mqtt/PlaystationPower', payload '{"current":0,"device":{"applicationVersion":65,"dateCode":"","friendlyName":"PlaystationPower","hardwareVersion":1,"ieeeAddr":"0x588e81fffed39555","manufacturerID":4098,"manufacturerName":"_TZ3000_g5xawfcq","model":"TS0121_plug","networkAddress":53528,"powerSource":"Mains (single phase)","stackVersion":0,"type":"Router","zclVersion":3},"energy":34.54,"indicator_mode":"off/on","last_seen":"2024-05-04T20:28:57+02:00","linkquality":208,"power":0,"power_outage_memory":"restore","state":"OFF","voltage":234}' [2024-05-04 20:28:57] debug: zh:ember: ~~~> [ZCL to=53528 apsFrame={"profileId":260,"clusterId":1794,"sourceEndpoint":1,"destinationEndpoint":1,"options":4352,"groupId":0,"sequence":0} header={"frameControl":{"reservedBits":0,"frameType":0,"direction":1,"disableDefaultResponse":true,"manufacturerSpecific":false},"manufacturerCode":null,"transactionSequenceNumber":16,"commandIdentifier":11}] [2024-05-04 20:28:57] debug: zh:ember:ezsp: ===> [FRAME: ID=52:"SEND_UNICAST" Seq=55 Len=26] [2024-05-04 20:28:57] debug: zh:ember:uart:ash: ---> [FRAME type=DATA frmTx=7 frmRx=1] [2024-05-04 20:28:57] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:57] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-05-04 20:28:57] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=1] Added to rxQueue [2024-05-04 20:28:57] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=2] [2024-05-04 20:28:57] debug: zh:ember:ezsp: <=== [FRAME: ID=52:"SEND_UNICAST" Seq=55 Len=7] [2024-05-04 20:28:57] debug: zh:ember:ezsp: ~~~> [SENT type=DIRECT apsSequence=87 messageTag=5 status=SUCCESS] [2024-05-04 20:28:57] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:57] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-05-04 20:28:57] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=2] Added to rxQueue [2024-05-04 20:28:57] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=3] [2024-05-04 20:28:57] debug: zh:ember:ezsp: <=== [FRAME: ID=196:"INCOMING_NETWORK_STATUS_HANDLER" Seq=55 Len=8] [2024-05-04 20:28:57] debug: zh:ember:ezsp: ezspIncomingNetworkStatusHandler(): callback called with: [errorCode=ROUTE_ERROR_ADDRESS_CONFLICT], [target=0] [2024-05-04 20:28:57] warning: zh:ember:ezsp: Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0". [2024-05-04 20:28:57] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-05-04 20:28:57] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0] [2024-05-04 20:28:57] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0 frmNum=3] Added to rxQueue [2024-05-04 20:28:57] debug: zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=4] [2024-05-04 20:28:57] debug: zh:ember:ezsp: <=== [FRAME: ID=196:"INCOMING_NETWORK_STATUS_HANDLER" Seq=55 Len=8] [2024-05-04 20:28:57] debug: zh:ember:ezsp: ezspIncomingNetworkStatusHandler(): callback called with: [errorCode=ROUTE_ERROR_ADDRESS_CONFLICT], [target=0] [2024-05-04 20:28:57] warning: zh:ember:ezsp: Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0". ```
lettore commented 6 months ago

@LDprg That's likely a battery-powered device that needs to wake up before it can configure properly. Try pushing a button on it before doing the configure. (You may need to push the button at 2-3 seconds intervals until it's done to keep it awake.)

Can someone with the Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0". issue provide a full debug-level log from z2m start to after that error starts occurring?

PS: Also, anyone not using a firmware from darkxst, please switch to it (Sonoff Dongle E 7.4.1). There has been issues with some others. #21462 (reply in thread)

Mine is not battery powered and without any changes works fine with EZSP, just when turning to EMBER driver after initialization it reports Received network/route error ROUTE_ERROR_ADDRESS_CONFLICT for "0". more time per second, it doesn't receive remote commands , and the same as @phenix1990 after some minutes it hangs up as the board is not responding anymore. In fact to have it working again I have to remove it from USB port and replug. The only problem I have with 1.37.0 with EZSP and Sonoff Dongle E 7.4.2 is that when I start pairing it throws another error, ERROR : Received undefined command from '0'. This don't affect anything, pairing works as expected. I think ember driver is not mature enough for production.

Nerivec commented 6 months ago

@phenix1990 You should be able to upload the file directly next time with Attach files πŸ˜‰

Can you please check with ezsp, if you see the same messages in the logs? In ember this is a warning, but in ezsp, it is a debug so you would not see it unless you are looking for it in the logs directly (you will need log level set to debug of course). Look for lines that say

handleNetworkStatus: nwk="0", errorCode="13"

which is the equivalent of the ones you are receiving with ember.

phenix1990 commented 6 months ago

@Nerivec yep, found this error with ezsp

handleNetworkStatus: nwk=0, errorCode=13

so its not related to ember? I also updated z2m from 1.32.2 to 1.37 due to some interesting changes. As mentioned other change was switching from Slaesh's CC2652RB stick to sonof dongle-e. And pi4 to pi5.

A lot of changes but i was optimistic. Now its dark and i cant control some lights from time to time. Good my wife already sleeping today :innocent:

Nerivec commented 6 months ago

When you switched from zstack to ezsp/ember, you re-paired everything, correct? Just making sure that by some weird coincidence you didn't manage to start ezsp/ember with a zstack-based network... πŸ˜…

You may have to re-pair devices one by one, until you start seeing the error again (make sure to run the network with zero devices for a few minutes first, just in case the error appears right away for some reason...). You don't have many, so it should be pretty quick. Easiest way to get a "clean slate" (remove all devices and ensure the creation of a new network), is to use GENERATE for network settings (also pick a good channel while you're at it, see docs) Basically something like this:

advanced:
  channel: 20
  network_key: GENERATE
  pan_id: GENERATE
  ext_pan_id: GENERATE
phenix1990 commented 6 months ago

Infact i didnt re-paired all devices because it seem to work for some people without.

For most of my devices re-pairing is no problem, just 3 hard wired ones will be a bit painfull to process. But then i have a task for the rest of the weekend. Thanks for the help so far!

Update: just 3 devices later i have repeating the same error.

[2024-05-04 23:17:38] debug:    z2m: MQTT publish: topic 'zigbee2mqtt/AirQualityTester', payload '{"co2":381,"device":{"applicationVersion":70,"dateCode":"","friendlyName":"AirQualityTester","hardwareVersion":1,"ieeeAddr":"0xa4c13874fb41ee57","manufacturerID":4417,"manufacturerName":"_TZE200_dwcarsat","model":"TS0601_smart_air_house_keeper","networkAddress":18694,"powerSource":"Mains (single phase)","stackVersion":0,"type":"Router","zclVersion":3},"formaldehyd":7,"humidity":57.5,"last_seen":"2024-05-04T23:17:23+02:00","linkquality":144,"pm25":3,"temperature":20.1,"voc":34}'
[2024-05-04 23:17:38] debug:    z2m: MQTT publish: topic 'zigbee2mqtt/bridge/response/device/rename', payload '{"data":{"from":"0xa4c13874fb41ee57","homeassistant_rename":false,"to":"AirQualityTester"},"status":"ok","transaction":"6sr6u-3"}'
[2024-05-04 23:17:38] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-04 23:17:38] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-04 23:17:38] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4 frmNum=1] Added to rxQueue
...
[2024-05-04 23:17:38] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA]
[2024-05-04 23:17:38] debug:    zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4]
[2024-05-04 23:17:38] debug:    zh:ember:uart:ash: <--- [FRAME type=ERROR]
[2024-05-04 23:17:38] error:    zh:ember:uart:ash: Received ERROR from NCP, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT.
[2024-05-04 23:17:38] error:    zh:ember:uart:ash: ASH disconnected | NCP status: ASH_NCP_FATAL_ERROR
[2024-05-04 23:17:38] debug:    zh:ember:uart:ash: Error while parsing received frame in NOT_CONNECTED state (flags=0), status=ASH_NCP_FATAL_ERROR.
[2024-05-04 23:17:38] debug:    zh:ember:uart:ash: ---> [FRAME type=ACK frmRx=6]
[2024-05-04 23:17:38] debug:    zh:ember:ezsp: <=== [FRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=115 Len=38]
[2024-05-04 23:17:38] debug:    zh:ember:ezsp: ezspIncomingMessageHandler(): callback called with: [type=UNICAST], [apsFrame={"profileId":260,"clusterId":61184,"sourceEndpoint":1,"destinationEndpoint":1,"options":256,"groupId":0,"sequence":97}], [lastHopLqi=144], [lastHopRssi=192], [sender=18694], [bindingIndex=255], [addressIndex=255], [messageContents=099a02000012020004000000cb]
[2024-05-04 23:17:38] debug:    zh:controller: Received payload: clusterID=61184, address=18694, groupID=0, endpoint=1, destinationEndpoint=1, wasBroadcast=false, linkQuality=144, frame={"header":{"frameControl":{"frameType":1,"manufacturerSpecific":false,"direction":1,"disableDefaultResponse":false,"reservedBits":0},"manufacturerCode":null,"transactionSequenceNumber":154,"commandIdentifier":2},"payload":{"seq":0,"dpValues":[{"dp":18,"datatype":2,"data":{"type":"Buffer","data":[0,0,0,203]}}]},"command":{"ID":2,"parameters":[{"name":"seq","type":33},{"name":"dpValues","type":1011}],"name":"dataReport"}}
[2024-05-04 23:17:38] debug:    zh:controller:endpoint: ZCL command 0xa4c13874fb41ee57/1 manuSpecificTuya.defaultRsp({"cmdId":2,"statusCode":0}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":154,"writeUndiv":false})
[2024-05-04 23:17:38] debug:    zh:ember:queue: Status queue=0 priorityQueue=0.
[2024-05-04 23:17:38] debug:    z2m: Received Zigbee message from 'AirQualityTester', type 'commandDataReport', cluster 'manuSpecificTuya', data '{"dpValues":[{"data":{"data":[0,0,0,203],"type":"Buffer"},"datatype":2,"dp":18}],"seq":0}' from endpoint 1 with groupID 0
[2024-05-04 23:17:38] debug:    z2m: MQTT publish: topic 'zigbee2mqtt/AirQualityTester', payload '{"co2":381,"device":{"applicationVersion":70,"dateCode":"","friendlyName":"AirQualityTester","hardwareVersion":1,"ieeeAddr":"0xa4c13874fb41ee57","manufacturerID":4417,"manufacturerName":"_TZE200_dwcarsat","model":"TS0601_smart_air_house_keeper","networkAddress":18694,"powerSource":"Mains (single phase)","stackVersion":0,"type":"Router","zclVersion":3},"formaldehyd":7,"humidity":57.5,"last_seen":"2024-05-04T23:17:38+02:00","linkquality":144,"pm25":3,"temperature":20.3,"voc":34}'
[2024-05-04 23:17:38] debug:    zh:ember: ~~~> [ZCL to=18694 apsFrame={"profileId":260,"clusterId":61184,"sourceEndpoint":1,"destinationEndpoint":1,"options":4352,"groupId":0,"sequence":0} header={"frameControl":{"reservedBits":0,"frameType":0,"direction":0,"disableDefaultResponse":true,"manufacturerSpecific":false},"manufacturerCode":null,"transactionSequenceNumber":154,"commandIdentifier":11}]
[2024-05-04 23:17:38] debug:    zh:ember:ezsp: [SEND COMMAND] NOT CONNECTED
[2024-05-04 23:17:38] debug:    zh:ember:queue: Dispatching deferred: Network not ready
[2024-05-04 23:17:38] debug:    zh:ember:queue: Dispatching stopped; queue=1 priorityQueue=0
[2024-05-04 23:17:38] debug:    zh:ember:uart:ash: Error while parsing received frame in NOT_CONNECTED state (flags=0), status=ASH_NCP_FATAL_ERROR.
[2024-05-04 23:17:40] debug:    zh:ember:queue: Dispatching started.
[2024-05-04 23:17:40] debug:    zh:ember: ~~~> [ZCL to=18694 apsFrame={"profileId":260,"clusterId":61184,"sourceEndpoint":1,"destinationEndpoint":1,"options":4352,"groupId":0,"sequence":0} header={"frameControl":{"reservedBits":0,"frameType":0,"direction":0,"disableDefaultResponse":true,"manufacturerSpecific":false},"manufacturerCode":null,"transactionSequenceNumber":154,"commandIdentifier":11}]
[2024-05-04 23:17:40] error:    zh:ember:ezsp: [SEND COMMAND] Cannot send second one before processing response from first one.
[2024-05-04 23:17:40] debug:    zh:controller:endpoint: ZCL command 0xa4c13874fb41ee57/1 manuSpecificTuya.defaultRsp({"cmdId":2,"statusCode":0}, {"timeout":10000,"disableResponse":false,"disableRecovery":false,"disableDefaultResponse":true,"direction":0,"srcEndpoint":null,"reservedBits":0,"manufacturerCode":null,"transactionSequenceNumber":154,"writeUndiv":false}) failed (ERROR_INVALID_CALL)
[2024-05-04 23:17:40] error:    zh:controller:device: Default response to 0xa4c13874fb41ee57 failed

A bit later i wasnt able to activate join of new devices and got this error every time I try:

[2024-05-04 23:27:32] error:    zh:controller:device: Default response to 0xa4c13874fb41ee57 failed
[2024-05-04 23:28:51] debug:    z2m: Received MQTT message on 'zigbee2mqtt/bridge/request/permit_join' with data '{"device":null,"time":254,"transaction":"6sr6u-5","value":true}'
[2024-05-04 23:28:51] info:     z2m: Zigbee: allowing new devices to join.
[2024-05-04 23:28:51] debug:    zh:ember:queue: Status queue=0 priorityQueue=0.
[2024-05-04 23:28:51] error:    zh:ember:ezsp: [SEND COMMAND] Cannot send second one before processing response from first one.
[2024-05-04 23:28:51] error:    z2m: Request 'zigbee2mqtt/bridge/request/permit_join' failed with error: 'ERROR_INVALID_CALL'
[2024-05-04 23:28:51] debug:    z2m: Error: ERROR_INVALID_CALL
    at Ezsp.startCommand (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:462:19)
    at Ezsp.ezspImportTransientKey (/app/node_modules/zigbee-herdsman/src/adapter/ember/ezsp/ezsp.ts:5922:14)
    at preJoining (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:3004:55)
    at Object.func (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/emberAdapter.ts:3071:49)
    at EmberRequestQueue.dispatch (/app/node_modules/zigbee-herdsman/src/adapter/ember/adapter/requestQueue.ts:117:58)
    at listOnTimeout (node:internal/timers:569:17)
    at processTimers (node:internal/timers:512:7)
[2024-05-04 23:28:51] debug:    z2m: MQTT publish: topic 'zigbee2mqtt/bridge/response/permit_join', payload '{"data":{},"error":"ERROR_INVALID_CALL","status":"error","transaction":"6sr6u-5"}'
[2024-05-04 23:31:59] debug:    z2m: Saving state to file /app/data/state.json
[2024-05-04 23:32:24] debug:    z2m: Received MQTT message on 'zigbee2mqtt/bridge/request/permit_join' with data '{"device":null,"time":254,"transaction":"6sr6u-6","value":true}'
[2024-05-04 23:32:24] info:     z2m: Zigbee: allowing new devices to join.
[2024-05-04 23:32:24] debug:    zh:ember:queue: Status queue=0 priorityQueue=0.
[2024-05-04 23:32:24] error:    zh:ember:ezsp: [SEND COMMAND] Cannot send second one before processing response from first one.
[2024-05-04 23:32:24] error:    z2m: Request 'zigbee2mqtt/bridge/request/permit_join' failed with error: 'ERROR_INVALID_CALL'
...(repeats for every click)

I added the complete log of the beginning of reconnection after generating new keys and IDs. The issue started from first device, before no errors except zh:ember:uart:ash: Received frame with CRC error

The first device is a Phillips Hue motion sensor. startOfReconnection.log

fred-gb commented 6 months ago

Bonjour, πŸ‘‹πŸ»

After somes days. It's a very good surprise for me.

First step: upgrade to zigbee2mqtt, firmware 7.4.2, drivers EZSP

First good surprise, my Button PTM216 finally works!

I read in the last few days, that switching to ember drivers will cause re-inclusion of modules. So this morning I'm getting ready to do this.

https://github.com/Koenkk/zigbee2mqtt/assets/17061623/126a71f6-6c6e-4a9b-bb85-5328a240fef3

πŸ˜…

I switched to EMBER drivers in debug mode and... ALL WORKS FINE WITHOUT NEED REINCLUDED ANY DEVICE! πŸ₯³

Very nice surprise to start this day!

Now I'm waiting for next z2m release after https://github.com/Koenkk/zigbee-herdsman/pull/1052

I let open this issue for @phenix1990 .

Nerivec commented 6 months ago

@phenix1990 I included a few fixes for the next release (hotfix coming out soon). Let me know how it goes after that.

phenix1990 commented 6 months ago

@phenix1990 I included a few fixes for the next release (hotfix coming out soon). Let me know how it goes after that.

I already updated z2m but with older adapter version and ezsp driver. Tomorrow evening I hopefully will have time to test with ember and 7.4.1 Firmware.

Update: Gone back to ember and firmware 7.4.1 and no errors so far the first 2 hours. I will check if it stays like that for a whole day but so far so good πŸ‘

Nerivec commented 6 months ago

Closing this to avoid mixing issues any further. @phenix1990 If you encounter any trouble, please open a new issue.

zerpex commented 5 months ago

Hi there,

Same issue with SonOff Dongle E 7.4.2 firmware even with z2m 1.38.0-dev. Only way to recover : switch back to ezsp.

LDprg commented 5 months ago

Hi there,

Same issue with SonOff Dongle E 7.4.2 firmware even with z2m 1.38.0-dev. Only way to recover : switch back to ezsp.

Try 7.4.3 firmware downloaded from https://github.com/darkxst/silabs-firmware-builder/blob/4.4.3/firmware_builds/zbdonglee/ncp-uart-hw-v7.4.3.0-zbdonglee-115200.gbl

@zerpex You also may need to change network ids and reconnect all devices. Because you won't be able to change the driver when other devices keep the network up with the same id. So you either completely power off all router devices or reconnect them into a new network. Config for devices is saved network independent in the config file.

See your logs for errors, they mostly tell you the problem.

zerpex commented 5 months ago

Hi @LDprg . I just updated to 7.4.3. This is better (Z2M is usable) and seems to work. Anyway, I still have the ROUTE_ERROR_ADDRESS_CONFLICT for "0".

How can I change this network ID ? Had a look around, be I was unable to find where...

phenix1990 commented 5 months ago

Hi @LDprg . I just updated to 7.4.3. This is better (Z2M is usable) and seems to work. Anyway, I still have the ROUTE_ERROR_ADDRESS_CONFLICT for "0".

How can I change this network ID ? Had a look around, be I was unable to find where...

its written some posts above. Just enter the keyword Generate in your z2m config and repair your devices. also was necessary for me.

advanced:
  channel: 20
  network_key: GENERATE
  pan_id: GENERATE
  ext_pan_id: GENERATE
LDprg commented 5 months ago

@zerpex You will need to set following flags in the config to GENERATE. Z2M will automatically fill them with new values

advanced:
  channel: 20
  pan_id: GENERATE
  ext_pan_id: GENERATE
  network_key: GENERATE

You might also want to delete the mqtt cache since it might cause weird malformed data in mqtt. This shouldn't affect zigbee2mqtt directly.

zerpex commented 5 months ago

Thanks a lot. I confiirm that with firmware 7.4.3 and these parameters, everything works with ember !