zigbee2mqtt icon indicating copy to clipboard operation
zigbee2mqtt copied to clipboard
Published 1 month ago • verified publisher icon Koenkk

Sonoff ZBDongle-E ember adapter fails with ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT

Open SoulofAkuma opened this issue 1 year ago • 3 comments

What happened?

Hi,

I tried to setup a new ZBDongle-E controller using zigbee2mqtt with home assistant and mosquitto today. I have tried multiple 7.4.x firmware versions (including the most recent one) and all of them caused the below issue for me. The closest I got to a working zigbee2mqtt instance was this one.

I am a developer and would be happy to help (and contribute) regarding this issue, if that would help.

What did you expect to happen?

I expected the adapter to work with the latest firmware on my new dongle.

How to reproduce it (minimal and precise)

I am using a new ZBDongle-E flashed with the latest firmware on a new Rasberry Pi 5. The compose.yaml I am using is the following:

services:
  homeassistant:
    container_name: homeassistant
    image: "ghcr.io/home-assistant/home-assistant:stable"
    volumes:
      - /home/mallert2/smarthome/homeassistant:/config
      - /etc/localtime:/etc/localtime:ro
      - /run/dbus:/run/dbus:ro
    restart: unless-stopped
    privileged: true
    network_mode: host

  portainer:
    container_name: portainer
    image: portainer/portainer-ce
    restart: always
    ports:
      - "9000:9000/tcp"
    environment:
      - TZ=Europe/Berlin
    volumes:
      - /var/run/docker.sock:/var/run/docker.sock
      - /home/mallert2/smarthome/portainer:/data

  mosquitto:
    image: eclipse-mosquitto:2.0
    container_name: mosquitto
    restart: unless-stopped
    volumes:
      - /home/mallert2/smarthome/mosquitto:/mosquitto
      - /home/mallert2/smarthome/mosquitto/data:/mosquitto/data
      - /home/mallert2/smarthome/mosquitto/log:/mosquitto/log
    ports:
      - 1883:1883
      - 9001:9001

  zigbee2mqtt:
    container_name: zigbee2mqtt
    restart: unless-stopped
    image: koenkk/zigbee2mqtt
    volumes:
      - ./zigbee2mqtt:/app/data
      - /run/udev:/run/udev:ro
    ports:
      - 8080:8080
    environment:
      - TZ=Europe/Berlin
    devices:
      - /dev/ttyUSB0:/dev/ttyUSB0

My zigbee2mqtt configuration is the following:

homeassistant: true
permit_join: true
mqtt:
  base_topic: zigbee2mqtt
  server: mqtt://192.168.178.47
serial:
  port: /dev/ttyUSB0
  adapter: ember
  rtscts: false
frontend:
  port: 8080
  server: 192.168.178.47
advanced:
  network_key:
    - 123
    - 101
    - 240
    - 11
    - 22
    - 176
    - 175
    - 118
    - 164
    - 65
    - 135
    - 74
    - 113
    - 17
    - 80
    - 213
  homeassistant_legacy_entity_attributes: false
  legacy_api: false
  legacy_availability_payload: false
  log_level: debug
device_options:
  legacy: false

My mosquitto instance does not use authentication and is also not causing any issues.

Running docker compose up with this setup, causes the issue I posted the log for.

Zigbee2MQTT version

1.40.2

Adapter firmware version

7.4.3

Adapter

EmberZNet

Setup

Docker Compose container

Debug log

[2024-10-03 02:13:36] info: z2m: Logging to console, file (filename: log.log) [2024-10-03 02:13:36] debug: z2m: Loaded state from file /app/data/state.json [2024-10-03 02:13:36] info: z2m: Starting Zigbee2MQTT version 1.40.2 (commit #e06848d) [2024-10-03 02:13:36] debug: z2m: sd-notify loaded [2024-10-03 02:13:36] info: z2m: Starting zigbee-herdsman (2.1.3) [2024-10-03 02:13:36] debug: z2m: Using zigbee-herdsman with settings: '"{"network":{"panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11],"networkKey":"HIDDEN"},"databasePath":"/app/data/database.db","databaseBackupPath":"/app/data/database.db.backup","backupPath":"/app/data/coordinator_backup.json","serialPort":{"rtscts":false,"path":"/dev/ttyUSB0","adapter":"ember"},"adapter":{"disableLED":false}}"' [2024-10-03 02:13:36] info: zh:ember: Using default stack config. [2024-10-03 02:13:36] debug: zh:controller: Starting with options '{"network":{"networkKeyDistribute":false,"networkKey":"HIDDEN","panID":6754,"extendedPanID":[221,221,221,221,221,221,221,221],"channelList":[11]},"serialPort":{"rtscts":false,"path":"/dev/ttyUSB0","adapter":"ember"},"adapter":{"disableLED":false},"databasePath":"/app/data/database.db","databaseBackupPath":"/app/data/database.db.backup","backupPath":"/app/data/coordinator_backup.json"}' [2024-10-03 02:13:36] info: zh:ember: ======== Ember Adapter Starting ======== [2024-10-03 02:13:36] info: zh:ember:ezsp: ======== EZSP starting ======== [2024-10-03 02:13:36] info: zh:ember:uart:ash: ======== ASH Adapter reset ======== [2024-10-03 02:13:36] info: zh:ember:uart:ash: RTS/CTS config is off, enabling software flow control. [2024-10-03 02:13:36] debug: zh:ember:uart:ash: Opening serial port with {"path":"/dev/ttyUSB0","baudRate":115200,"rtscts":false,"autoOpen":false,"parity":"none","stopBits":1,"xon":true,"xoff":true} [2024-10-03 02:13:36] info: zh:ember:uart:ash: Serial port opened [2024-10-03 02:13:36] info: zh:ember:uart:ash: ======== ASH starting ======== [2024-10-03 02:13:36] debug: zh:ember:uart:ash: ---> [FRAME type=RST] [2024-10-03 02:13:36] debug: zh:ember:uart:ash: Waiting for RSTACK... 0/2500 [2024-10-03 02:13:36] debug: zh:ember:uart:ash: Waiting for RSTACK... 100/2500 [2024-10-03 02:13:36] debug: zh:ember:uart:ash: Waiting for RSTACK... 200/2500 [2024-10-03 02:13:36] debug: zh:ember:uart:ash: Waiting for RSTACK... 300/2500 [2024-10-03 02:13:36] debug: zh:ember:uart:ash: Waiting for RSTACK... 400/2500 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: Waiting for RSTACK... 500/2500 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: Waiting for RSTACK... 600/2500 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: Waiting for RSTACK... 700/2500 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: Waiting for RSTACK... 800/2500 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: Waiting for RSTACK... 900/2500 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: Waiting for RSTACK... 1000/2500 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=RSTACK] [2024-10-03 02:13:37] info: zh:ember:uart:ash: ======== ASH connected ======== [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=0 [2024-10-03 02:13:37] info: zh:ember:uart:ash: ======== ASH started ======== [2024-10-03 02:13:37] info: zh:ember:ezsp: ======== EZSP started ======== [2024-10-03 02:13:37] debug: zh:ember:ezsp: ===> [FRAME: ID=0:"VERSION" Seq=0 Len=4] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=0 frmRx=0 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=0 frmTx=1) [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=1 frmNum=0 Added to rxQueue [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=1 [2024-10-03 02:13:37] debug: zh:ember:ezsp: <=== [FRAME: ID=0:"VERSION" Seq=0 Len=7] [2024-10-03 02:13:37] debug: zh:ember:ezsp: ===> [FRAME: ID=0:"VERSION" Seq=1 Len=6] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=1 frmRx=1 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=1 frmTx=2) [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=2 frmNum=1 Added to rxQueue [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=2 [2024-10-03 02:13:37] debug: zh:ember:ezsp: <=== [FRAME: ID=0:"VERSION" Seq=1 Len=9] [2024-10-03 02:13:37] info: zh:ember: Adapter EZSP protocol version (13) lower than Host. Switched. [2024-10-03 02:13:37] debug: zh:ember: Adapter info: EZSPVersion=13 StackType=2 StackVersion=29744 [2024-10-03 02:13:37] debug: zh:ember:ezsp: ===> [FRAME: ID=170:"GET_VALUE" Seq=2 Len=6] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=2 frmRx=2 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3](ackRx=2 frmTx=3) [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=3 frmNum=2 Added to rxQueue [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=3 [2024-10-03 02:13:37] debug: zh:ember:ezsp: <=== [FRAME: ID=170:"GET_VALUE" Seq=2 Len=14] [2024-10-03 02:13:37] info: zh:ember: Adapter version info: {"ezsp":13,"revision":"7.4.3 [GA]","build":0,"major":7,"minor":4,"patch":3,"special":0,"type":170} [2024-10-03 02:13:37] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=3 Len=8] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=3 frmRx=3 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4](ackRx=3 frmTx=4) [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=4 frmNum=3 Added to rxQueue [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=4 [2024-10-03 02:13:37] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=3 Len=6] [2024-10-03 02:13:37] debug: zh:ember: [EzspConfigId] SET 'TRUST_CENTER_ADDRESS_CACHE_SIZE' TO '2' with status=OK. [2024-10-03 02:13:37] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=4 Len=8] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=4 frmRx=4 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5](ackRx=4 frmTx=5) [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=5 frmNum=4 Added to rxQueue [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=5 [2024-10-03 02:13:37] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=4 Len=6] [2024-10-03 02:13:37] debug: zh:ember: [EzspConfigId] SET 'INDIRECT_TRANSMISSION_TIMEOUT' TO '7680' with status=OK. [2024-10-03 02:13:37] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=5 Len=8] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=5 frmRx=5 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6](ackRx=5 frmTx=6) [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=6 frmNum=5 Added to rxQueue [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=6 [2024-10-03 02:13:37] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=5 Len=6] [2024-10-03 02:13:37] debug: zh:ember: [EzspConfigId] SET 'MAX_HOPS' TO '30' with status=OK. [2024-10-03 02:13:37] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=6 Len=8] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=6 frmRx=6 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7](ackRx=6 frmTx=7) [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=7 frmNum=6 Added to rxQueue [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=7 [2024-10-03 02:13:37] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=6 Len=6] [2024-10-03 02:13:37] debug: zh:ember: [EzspConfigId] SET 'SUPPORTED_NETWORKS' TO '1' with status=OK. [2024-10-03 02:13:37] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=7 Len=7] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=7 frmRx=7 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0](ackRx=7 frmTx=0) [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=0 frmNum=7 Added to rxQueue [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=0 [2024-10-03 02:13:37] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=7 Len=6] [2024-10-03 02:13:37] debug: zh:ember: [EzspPolicyId] SET 'BINDING_MODIFICATION_POLICY' TO '18' with status=OK. [2024-10-03 02:13:37] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=8 Len=7] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=0 frmRx=0 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=0 frmTx=1) [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=1 frmNum=0 Added to rxQueue [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=1 [2024-10-03 02:13:37] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=8 Len=6] [2024-10-03 02:13:37] debug: zh:ember: [EzspPolicyId] SET 'MESSAGE_CONTENTS_IN_CALLBACK_POLICY' TO '64' with status=OK. [2024-10-03 02:13:37] debug: zh:ember:ezsp: ===> [FRAME: ID=171:"SET_VALUE" Seq=9 Len=9] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=1 frmRx=1 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=1 frmTx=2) [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=2 frmNum=1 Added to rxQueue [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=2 [2024-10-03 02:13:37] debug: zh:ember:ezsp: <=== [FRAME: ID=171:"SET_VALUE" Seq=9 Len=6] [2024-10-03 02:13:37] debug: zh:ember: [EzspValueId] SET 'TRANSIENT_DEVICE_TIMEOUT' TO '16,39' with status=OK. [2024-10-03 02:13:37] debug: zh:ember:ezsp: ===> [FRAME: ID=21:"SET_MANUFACTURER_CODE" Seq=10 Len=7] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=2 frmRx=2 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3](ackRx=2 frmTx=3) [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=3 frmNum=2 Added to rxQueue [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=3 [2024-10-03 02:13:37] debug: zh:ember:ezsp: <=== [FRAME: ID=21:"SET_MANUFACTURER_CODE" Seq=10 Len=5] [2024-10-03 02:13:37] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=11 Len=8] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=3 frmRx=3 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4](ackRx=3 frmTx=4) [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=4 frmNum=3 Added to rxQueue [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=4 [2024-10-03 02:13:37] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=11 Len=6] [2024-10-03 02:13:37] debug: zh:ember: [EzspConfigId] SET 'STACK_PROFILE' TO '2' with status=OK. [2024-10-03 02:13:37] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=12 Len=8] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=4 frmRx=4 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5](ackRx=4 frmTx=5) [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=5 frmNum=4 Added to rxQueue [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=5 [2024-10-03 02:13:37] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=12 Len=6] [2024-10-03 02:13:37] debug: zh:ember: [EzspConfigId] SET 'SECURITY_LEVEL' TO '5' with status=OK. [2024-10-03 02:13:37] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=13 Len=8] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=5 frmRx=5 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6](ackRx=5 frmTx=6) [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=6 frmNum=5 Added to rxQueue [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=6 [2024-10-03 02:13:37] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=13 Len=6] [2024-10-03 02:13:37] debug: zh:ember: [EzspConfigId] SET 'MAX_END_DEVICE_CHILDREN' TO '32' with status=OK. [2024-10-03 02:13:37] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=14 Len=8] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=6 frmRx=6 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7](ackRx=6 frmTx=7) [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=7 frmNum=6 Added to rxQueue [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=7 [2024-10-03 02:13:37] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=14 Len=6] [2024-10-03 02:13:37] debug: zh:ember: [EzspConfigId] SET 'END_DEVICE_POLL_TIMEOUT' TO '8' with status=OK. [2024-10-03 02:13:37] debug: zh:ember:ezsp: ===> [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=15 Len=8] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=7 frmRx=7 [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:37] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0](ackRx=7 frmTx=0) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=0 frmNum=7 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=0 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=83:"SET_CONFIGURATION_VALUE" Seq=15 Len=6] [2024-10-03 02:13:38] debug: zh:ember: [EzspConfigId] SET 'TRANSIENT_KEY_TIMEOUT_S' TO '300' with status=OK. [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=171:"SET_VALUE" Seq=16 Len=8] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=0 frmRx=0 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=0 frmTx=1) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=1 frmNum=0 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=1 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=171:"SET_VALUE" Seq=16 Len=6] [2024-10-03 02:13:38] debug: zh:ember: [EzspValueId] SET 'CCA_THRESHOLD' TO '0' with status=OK. [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=17 Len=10] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=1 frmRx=1 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=1 frmTx=2) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=2 frmNum=1 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=2 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=17 Len=9] [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=2:"ADD_ENDPOINT" Seq=18 Len=63] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=2 frmRx=2 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3](ackRx=2 frmTx=3) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=3 frmNum=2 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=3 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=2:"ADD_ENDPOINT" Seq=18 Len=6] [2024-10-03 02:13:38] debug: zh:ember: Registered endpoint '1'. [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=19 Len=10] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=3 frmRx=3 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4](ackRx=3 frmTx=4) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=4 frmNum=3 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=4 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=19 Len=6] [2024-10-03 02:13:38] debug: zh:ember: Registered multicast table entry (0): {"multicastId":0,"endpoint":1,"networkIndex":0}. [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=20 Len=10] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=4 frmRx=4 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5](ackRx=4 frmTx=5) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=5 frmNum=4 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=5 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=20 Len=6] [2024-10-03 02:13:38] debug: zh:ember: Registered multicast table entry (1): {"multicastId":901,"endpoint":1,"networkIndex":0}. [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=21 Len=10] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=5 frmRx=5 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6](ackRx=5 frmTx=6) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=6 frmNum=5 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=6 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=3:"GET_EXTENDED_VALUE" Seq=21 Len=9] [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=2:"ADD_ENDPOINT" Seq=22 Len=17] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=6 frmRx=6 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7](ackRx=6 frmTx=7) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=7 frmNum=6 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=7 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=2:"ADD_ENDPOINT" Seq=22 Len=6] [2024-10-03 02:13:38] debug: zh:ember: Registered endpoint '242'. [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=23 Len=10] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=7 frmRx=7 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0](ackRx=7 frmTx=0) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=0 frmNum=7 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=0 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=100:"SET_MULTICAST_TABLE_ENTRY" Seq=23 Len=6] [2024-10-03 02:13:38] debug: zh:ember: Registered multicast table entry (2): {"multicastId":2948,"endpoint":242,"networkIndex":0}. [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=24 Len=7] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=0 frmRx=0 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=0 frmTx=1) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=1 frmNum=0 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=1 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=24 Len=6] [2024-10-03 02:13:38] debug: zh:ember: [EzspPolicyId] SET 'TC_KEY_REQUEST_POLICY' TO '81' with status=OK. [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=25 Len=7] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=1 frmRx=1 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=1 frmTx=2) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=2 frmNum=1 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=2 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=25 Len=6] [2024-10-03 02:13:38] debug: zh:ember: [EzspPolicyId] SET 'APP_KEY_REQUEST_POLICY' TO '96' with status=OK. [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=26 Len=7] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=2 frmRx=2 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3](ackRx=2 frmTx=3) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=3 frmNum=2 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=3 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=26 Len=6] [2024-10-03 02:13:38] debug: zh:ember: [EzspPolicyId] SET 'TRUST_CENTER_POLICY' TO '3' with status=OK. [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=23:"NETWORK_INIT" Seq=27 Len=7] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=3 frmRx=3 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4](ackRx=3 frmTx=4) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=4 frmNum=3 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4](ackRx=4 frmTx=4) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=4 frmNum=4 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=5 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=23:"NETWORK_INIT" Seq=27 Len=6] [2024-10-03 02:13:38] debug: zh:ember: [INIT TC] Network init status=OK. [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [CBFRAME: ID=25:"STACK_STATUS_HANDLER" Seq=27 Len=6] [2024-10-03 02:13:38] debug: zh:ember:ezsp: ezspStackStatusHandler(): callback called with: [status=NETWORK_UP] [2024-10-03 02:13:38] info: zh:ember: [STACK STATUS] Network up. [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=40:"GET_NETWORK_PARAMETERS" Seq=28 Len=5] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=4 frmRx=5 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5](ackRx=4 frmTx=5) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=5 frmNum=5 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=6 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=40:"GET_NETWORK_PARAMETERS" Seq=28 Len=27] [2024-10-03 02:13:38] debug: zh:ember: [INIT TC] Current adapter network: nodeType=COORDINATOR params={"extendedPanId":[221,221,221,221,221,221,221,221],"panId":6754,"radioTxPower":5,"radioChannel":11,"joinMethod":0,"nwkManagerId":0,"nwkUpdateId":0,"channels":134215680} [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=276:"EXPORT_KEY" Seq=29 Len=23] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=5 frmRx=6 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6](ackRx=5 frmTx=6) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=6 frmNum=6 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=7 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=276:"EXPORT_KEY" Seq=29 Len=25] [2024-10-03 02:13:38] info: zh:ember: [INIT TC] Adapter network matches config. [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=16:"SET_CONCENTRATOR" Seq=30 Len=15] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=6 frmRx=7 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7](ackRx=6 frmTx=7) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=7 frmNum=7 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=0 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=16:"SET_CONCENTRATOR" Seq=30 Len=6] [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=90:"SET_SOURCE_ROUTE_DISCOVERY_MODE" Seq=31 Len=6] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=7 frmRx=0 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=0](ackRx=7 frmTx=0) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=0 frmNum=0 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=1 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=90:"SET_SOURCE_ROUTE_DISCOVERY_MODE" Seq=31 Len=9] [2024-10-03 02:13:38] info: zh:ember: [CONCENTRATOR] Started source route discovery. 1242ms until next broadcast. [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=40:"GET_NETWORK_PARAMETERS" Seq=32 Len=5] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=0 frmRx=1 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=0 frmTx=1) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=1 frmNum=1 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=2 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=40:"GET_NETWORK_PARAMETERS" Seq=32 Len=27] [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=38:"GET_EUI64" Seq=33 Len=5] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=1 frmRx=2 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=2](ackRx=1 frmTx=2) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=2 frmNum=2 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=3 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=38:"GET_EUI64" Seq=33 Len=13] [2024-10-03 02:13:38] debug: zh:ember: [INIT] Network Ready! {"eui64":"0x8c65a3fffe512481","parameters":{"extendedPanId":[221,221,221,221,221,221,221,221],"panId":6754,"radioTxPower":5,"radioChannel":11,"joinMethod":0,"nwkManagerId":0,"nwkUpdateId":0,"channels":134215680}} [2024-10-03 02:13:38] debug: zh:controller: Started with result 'resumed' [2024-10-03 02:13:38] debug: zh:controller: Injected database: true, adapter: true [2024-10-03 02:13:38] debug: zh:controller:device: Request Queue (0x8c65a3fffe512481): default expiration timeout set to 0 [2024-10-03 02:13:38] info: z2m: zigbee-herdsman started (resumed) [2024-10-03 02:13:38] info: z2m: Coordinator firmware version: '{"meta":{"build":0,"ezsp":13,"major":7,"minor":4,"patch":3,"revision":"7.4.3 [GA]","special":0,"type":170},"type":"EmberZNet"}' [2024-10-03 02:13:38] debug: z2m: Zigbee network parameters: {"channel":11,"extendedPanID":15987178197214945000,"panID":6754} [2024-10-03 02:13:38] info: z2m: Currently 0 devices are joined. [2024-10-03 02:13:38] warning: z2m: permit_join set to true in configuration.yaml. [2024-10-03 02:13:38] warning: z2m: Allowing new devices to join. [2024-10-03 02:13:38] warning: z2m: Set permit_join to false once you joined all devices. [2024-10-03 02:13:38] info: z2m: Zigbee: allowing new devices to join. [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=273:"IMPORT_TRANSIENT_KEY" Seq=34 Len=30] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=2 frmRx=3 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=3](ackRx=2 frmTx=3) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=3 frmNum=3 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=4 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=273:"IMPORT_TRANSIENT_KEY" Seq=34 Len=9] [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=85:"SET_POLICY" Seq=35 Len=7] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=3 frmRx=4 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=4](ackRx=3 frmTx=4) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=4 frmNum=4 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=5 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=85:"SET_POLICY" Seq=35 Len=6] [2024-10-03 02:13:38] debug: zh:ember: [EzspPolicyId] SET 'TRUST_CENTER_POLICY' TO '3' with status=OK. [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=34:"PERMIT_JOINING" Seq=36 Len=6] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=4 frmRx=5 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5](ackRx=4 frmTx=5) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=5 frmNum=5 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=5](ackRx=5 frmTx=5) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=5 frmNum=6 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=7 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=34:"PERMIT_JOINING" Seq=36 Len=6] [2024-10-03 02:13:38] debug: zh:ember: Permit joining on coordinator for 254 sec. [2024-10-03 02:13:38] debug: zh:ember: ~~~> [ZDO PERMIT_JOINING_REQUEST BROADCAST to=65532 messageTag=1 payload=01fe01] [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=54:"SEND_BROADCAST" Seq=37 Len=24] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=5 frmRx=7 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [CBFRAME: ID=25:"STACK_STATUS_HANDLER" Seq=36 Len=6] [2024-10-03 02:13:38] debug: zh:ember:ezsp: ezspStackStatusHandler(): callback called with: [status=ZIGBEE_NETWORK_OPENED] [2024-10-03 02:13:38] info: zh:ember: [STACK STATUS] Network opened. [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=6](ackRx=5 frmTx=6) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=6 frmNum=7 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=0 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=54:"SEND_BROADCAST" Seq=37 Len=7] [2024-10-03 02:13:38] debug: zh:ember: ~~~> [SENT ZDO BROADCAST messageTag=1 apsSequence=157 status=OK] [2024-10-03 02:13:38] 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},"transactionSequenceNumber":2,"commandIdentifier":2}] [2024-10-03 02:13:38] debug: zh:ember:ezsp: ===> [FRAME: ID=54:"SEND_BROADCAST" Seq=38 Len=27] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=DATA frmTx=6 frmRx=0 [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7](ackRx=6 frmTx=7) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=7 frmNum=0 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=1 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [FRAME: ID=54:"SEND_BROADCAST" Seq=38 Len=7] [2024-10-03 02:13:38] debug: zh:ember:ezsp: ~~~> [SENT type=BROADCAST apsSequence=158 messageTag=1 status=OK] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7](ackRx=7 frmTx=7) [2024-10-03 02:13:38] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=7 frmNum=1 Added to rxQueue [2024-10-03 02:13:38] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=2 [2024-10-03 02:13:38] debug: zh:ember:ezsp: <=== [CBFRAME: ID=69:"INCOMING_MESSAGE_HANDLER" Seq=38 Len=30] [2024-10-03 02:13:38] 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":158}], [packetInfo:{"senderShortId":0,"senderLongId":"0xFFFFFFFFFFFFFFFF","bindingIndex":255,"addressIndex":255,"lastHopLqi":255,"lastHopRssi":0,"lastHopTimestamp":0}], [messageContents=1902020bfe00] [2024-10-03 02:13:39] info: z2m: Connecting to MQTT server at mqtt://192.168.178.47 [2024-10-03 02:13:39] debug: z2m: Using MQTT anonymous login [2024-10-03 02:13:39] info: z2m: Connected to MQTT server [2024-10-03 02:13:39] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload '{"state":"online"}' [2024-10-03 02:13:39] info: z2m: Started frontend on port 8080 [2024-10-03 02:13:39] debug: z2m: Discovering entities to Home Assistant in 5s [2024-10-03 02:13:39] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload '{"state":"online"}' [2024-10-03 02:13:39] info: z2m: Zigbee2MQTT started! [2024-10-03 02:13:39] debug: z2m:mqtt: Received MQTT message on 'homeassistant/binary_sensor/1221051039810110150109113116116_0x8c65a3fffe512481/connection_state/config' with data '{"device":{"hw_version":"EmberZNet 7.4.3 [GA]","identifiers":["zigbee2mqtt_bridge_0x8c65a3fffe512481"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.40.2"},"device_class":"connectivity","entity_category":"diagnostic","name":"Connection state","object_id":"zigbee2mqtt_bridge_connection_state","origin":{"name":"Zigbee2MQTT","sw":"1.40.2","url":"https://www.zigbee2mqtt.io"},"payload_off":"offline","payload_on":"online","state_topic":"zigbee2mqtt/bridge/state","unique_id":"bridge_0x8c65a3fffe512481_connection_state_zigbee2mqtt","value_template":"{{ value_json.state }}"}' [2024-10-03 02:13:39] debug: z2m:mqtt: Received MQTT message on 'homeassistant/binary_sensor/1221051039810110150109113116116_0x8c65a3fffe512481/restart_required/config' with data '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"availability_mode":"all","device":{"hw_version":"EmberZNet 7.4.3 [GA]","identifiers":["zigbee2mqtt_bridge_0x8c65a3fffe512481"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.40.2"},"device_class":"problem","enabled_by_default":false,"entity_category":"diagnostic","name":"Restart required","object_id":"zigbee2mqtt_bridge_restart_required","origin":{"name":"Zigbee2MQTT","sw":"1.40.2","url":"https://www.zigbee2mqtt.io"},"payload_off":false,"payload_on":true,"state_topic":"zigbee2mqtt/bridge/info","unique_id":"bridge_0x8c65a3fffe512481_restart_required_zigbee2mqtt","value_template":"{{ value_json.restart_required }}"}' [2024-10-03 02:13:39] debug: z2m:mqtt: Received MQTT message on 'homeassistant/button/1221051039810110150109113116116_0x8c65a3fffe512481/restart/config' with data '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"availability_mode":"all","command_topic":"zigbee2mqtt/bridge/request/restart","device":{"hw_version":"EmberZNet 7.4.3 [GA]","identifiers":["zigbee2mqtt_bridge_0x8c65a3fffe512481"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.40.2"},"device_class":"restart","name":"Restart","object_id":"zigbee2mqtt_bridge_restart","origin":{"name":"Zigbee2MQTT","sw":"1.40.2","url":"https://www.zigbee2mqtt.io"},"payload_press":"","unique_id":"bridge_0x8c65a3fffe512481_restart_zigbee2mqtt"}' [2024-10-03 02:13:39] debug: z2m:mqtt: Received MQTT message on 'homeassistant/select/1221051039810110150109113116116_0x8c65a3fffe512481/log_level/config' with data '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"availability_mode":"all","command_template":"{"options": {"advanced": {"log_level": "{{ value }}" } } }","command_topic":"zigbee2mqtt/bridge/request/options","device":{"hw_version":"EmberZNet 7.4.3 [GA]","identifiers":["zigbee2mqtt_bridge_0x8c65a3fffe512481"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.40.2"},"entity_category":"config","name":"Log level","object_id":"zigbee2mqtt_bridge_log_level","options":["error","warning","info","debug"],"origin":{"name":"Zigbee2MQTT","sw":"1.40.2","url":"https://www.zigbee2mqtt.io"},"state_topic":"zigbee2mqtt/bridge/info","unique_id":"bridge_0x8c65a3fffe512481_log_level_zigbee2mqtt","value_template":"{{ value_json.log_level | lower }}"}' [2024-10-03 02:13:39] debug: z2m:mqtt: Received MQTT message on 'homeassistant/sensor/1221051039810110150109113116116_0x8c65a3fffe512481/version/config' with data '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"availability_mode":"all","device":{"hw_version":"EmberZNet 7.4.3 [GA]","identifiers":["zigbee2mqtt_bridge_0x8c65a3fffe512481"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.40.2"},"entity_category":"diagnostic","icon":"mdi:zigbee","name":"Version","object_id":"zigbee2mqtt_bridge_version","origin":{"name":"Zigbee2MQTT","sw":"1.40.2","url":"https://www.zigbee2mqtt.io"},"state_topic":"zigbee2mqtt/bridge/info","unique_id":"bridge_0x8c65a3fffe512481_version_zigbee2mqtt","value_template":"{{ value_json.version }}"}' [2024-10-03 02:13:39] debug: z2m:mqtt: Received MQTT message on 'homeassistant/sensor/1221051039810110150109113116116_0x8c65a3fffe512481/coordinator_version/config' with data '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"availability_mode":"all","device":{"hw_version":"EmberZNet 7.4.3 [GA]","identifiers":["zigbee2mqtt_bridge_0x8c65a3fffe512481"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.40.2"},"enabled_by_default":false,"entity_category":"diagnostic","icon":"mdi:chip","name":"Coordinator version","object_id":"zigbee2mqtt_bridge_coordinator_version","origin":{"name":"Zigbee2MQTT","sw":"1.40.2","url":"https://www.zigbee2mqtt.io"},"state_topic":"zigbee2mqtt/bridge/info","unique_id":"bridge_0x8c65a3fffe512481_coordinator_version_zigbee2mqtt","value_template":"{{ value_json.coordinator.meta.revision }}"}' [2024-10-03 02:13:39] debug: z2m:mqtt: Received MQTT message on 'homeassistant/sensor/1221051039810110150109113116116_0x8c65a3fffe512481/network_map/config' with data '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"availability_mode":"all","device":{"hw_version":"EmberZNet 7.4.3 [GA]","identifiers":["zigbee2mqtt_bridge_0x8c65a3fffe512481"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.40.2"},"enabled_by_default":false,"entity_category":"diagnostic","json_attributes_template":"{{ value_json.data.value | tojson }}","json_attributes_topic":"zigbee2mqtt/bridge/response/networkmap","name":"Network map","object_id":"zigbee2mqtt_bridge_network_map","origin":{"name":"Zigbee2MQTT","sw":"1.40.2","url":"https://www.zigbee2mqtt.io"},"state_topic":"zigbee2mqtt/bridge/response/networkmap","unique_id":"bridge_0x8c65a3fffe512481_network_map_zigbee2mqtt","value_template":"{{ now().strftime('%Y-%m-%d %H:%M:%S') }}"}' [2024-10-03 02:13:39] debug: z2m:mqtt: Received MQTT message on 'homeassistant/sensor/1221051039810110150109113116116_0x8c65a3fffe512481/permit_join_timeout/config' with data '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"availability_mode":"all","device":{"hw_version":"EmberZNet 7.4.3 [GA]","identifiers":["zigbee2mqtt_bridge_0x8c65a3fffe512481"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.40.2"},"device_class":"duration","entity_category":"diagnostic","name":"Permit join timeout","object_id":"zigbee2mqtt_bridge_permit_join_timeout","origin":{"name":"Zigbee2MQTT","sw":"1.40.2","url":"https://www.zigbee2mqtt.io"},"state_topic":"zigbee2mqtt/bridge/info","unique_id":"bridge_0x8c65a3fffe512481_permit_join_timeout_zigbee2mqtt","unit_of_measurement":"s","value_template":"{{ iif(value_json.permit_join_timeout is defined, value_json.permit_join_timeout, None) }}"}' [2024-10-03 02:13:39] debug: z2m:mqtt: Received MQTT message on 'homeassistant/switch/1221051039810110150109113116116_0x8c65a3fffe512481/permit_join/config' with data '{"availability":[{"topic":"zigbee2mqtt/bridge/state","value_template":"{{ value_json.state }}"}],"availability_mode":"all","command_topic":"zigbee2mqtt/bridge/request/permit_join","device":{"hw_version":"EmberZNet 7.4.3 [GA]","identifiers":["zigbee2mqtt_bridge_0x8c65a3fffe512481"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.40.2"},"icon":"mdi:human-greeting-proximity","name":"Permit join","object_id":"zigbee2mqtt_bridge_permit_join","origin":{"name":"Zigbee2MQTT","sw":"1.40.2","url":"https://www.zigbee2mqtt.io"},"payload_off":"false","payload_on":"true","state_topic":"zigbee2mqtt/bridge/info","unique_id":"bridge_0x8c65a3fffe512481_permit_join_zigbee2mqtt","value_template":"{{ value_json.permit_join | lower }}"}' [2024-10-03 02:13:39] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:39] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7](ackRx=7 frmTx=7) [2024-10-03 02:13:39] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=7 frmNum=2 Added to rxQueue [2024-10-03 02:13:39] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=3 [2024-10-03 02:13:39] debug: zh:ember:ezsp: <=== [CBFRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=38 Len=22] [2024-10-03 02:13:39] debug: zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [status=OK], [type=BROADCAST], [indexOrDestination=65532], [apsFrame={"profileId":0,"clusterId":54,"sourceEndpoint":0,"destinationEndpoint":0,"options":256,"groupId":0,"sequence":157}], [messageTag=255] [2024-10-03 02:13:39] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:39] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=7](ackRx=7 frmTx=7) [2024-10-03 02:13:39] debug: zh:ember:uart:ash: <--- FRAME type=DATA ackNum=7 frmNum=3 Added to rxQueue [2024-10-03 02:13:39] debug: zh:ember:uart:ash: ---> FRAME type=ACK frmRx=4 [2024-10-03 02:13:39] debug: zh:ember:ezsp: <=== [CBFRAME: ID=63:"MESSAGE_SENT_HANDLER" Seq=38 Len=22] [2024-10-03 02:13:39] debug: zh:ember:ezsp: ezspMessageSentHandler(): callback called with: [status=OK], [type=BROADCAST], [indexOrDestination=65533], [apsFrame={"profileId":41440,"clusterId":33,"sourceEndpoint":242,"destinationEndpoint":242,"options":256,"groupId":0,"sequence":158}], [messageTag=1] [2024-10-03 02:13:44] debug: z2m: Discovering entities to Home Assistant [2024-10-03 02:13:44] info: z2m:mqtt: MQTT publish: topic 'homeassistant/binary_sensor/1221051039810110150109113116116_0x8c65a3fffe512481/connection_state/config', payload '{"device":{"hw_version":"EmberZNet 7.4.3 [GA]","identifiers":["zigbee2mqtt_bridge_0x8c65a3fffe512481"],"manufacturer":"Zigbee2MQTT","model":"Bridge","name":"Zigbee2MQTT Bridge","sw_version":"1.40.2"},"device_class":"connectivity","entity_category":"diagnostic","name":"Connection state","object_id":"zigbee2mqtt_bridge_connection_state","origin":{"name":"Zigbee2MQTT","sw":"1.40.2","url":"https://www.zigbee2mqtt.io"},"payload_off":"offline","payload_on":"online","state_topic":"zigbee2mqtt/bridge/state","unique_id":"bridge_0x8c65a3fffe512481_connection_state_zigbee2mqtt","value_template":"{{ value_json.state }}"}' [2024-10-03 02:13:44] debug: z2m: Skipping discovery of 'binary_sensor/1221051039810110150109113116116_0x8c65a3fffe512481/restart_required/config', already discovered [2024-10-03 02:13:44] debug: z2m: Skipping discovery of 'button/1221051039810110150109113116116_0x8c65a3fffe512481/restart/config', already discovered [2024-10-03 02:13:44] debug: z2m: Skipping discovery of 'select/1221051039810110150109113116116_0x8c65a3fffe512481/log_level/config', already discovered [2024-10-03 02:13:44] debug: z2m: Skipping discovery of 'sensor/1221051039810110150109113116116_0x8c65a3fffe512481/version/config', already discovered [2024-10-03 02:13:44] debug: z2m: Skipping discovery of 'sensor/1221051039810110150109113116116_0x8c65a3fffe512481/coordinator_version/config', already discovered [2024-10-03 02:13:44] debug: z2m: Skipping discovery of 'sensor/1221051039810110150109113116116_0x8c65a3fffe512481/network_map/config', already discovered [2024-10-03 02:13:44] debug: z2m: Skipping discovery of 'sensor/1221051039810110150109113116116_0x8c65a3fffe512481/permit_join_timeout/config', already discovered [2024-10-03 02:13:44] debug: z2m: Skipping discovery of 'switch/1221051039810110150109113116116_0x8c65a3fffe512481/permit_join/config', already discovered [2024-10-03 02:13:49] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:49] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=7 frmTx=7) [2024-10-03 02:13:49] debug: zh:ember:uart:ash: <-x- [FRAME type=DATA ackNum=1] Invalid ACK num; not within <7-7> [2024-10-03 02:13:49] debug: zh:ember:uart:ash: <-x- [FRAME type=DATA] Rejecting. 0142a1 [2024-10-03 02:13:49] debug: zh:ember:uart:ash: ---> FRAME type=NAK frmRx=4 [2024-10-03 02:13:50] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:50] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=7 frmTx=7) [2024-10-03 02:13:50] debug: zh:ember:uart:ash: <-x- [FRAME type=DATA ackNum=1] Invalid ACK num; not within <7-7> [2024-10-03 02:13:50] debug: zh:ember:uart:ash: <-x- [FRAME type=DATA] Rejecting. 0942a1 [2024-10-03 02:13:54] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:54] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=7 frmTx=7) [2024-10-03 02:13:54] debug: zh:ember:uart:ash: <-x- [FRAME type=DATA ackNum=1] Invalid ACK num; not within <7-7> [2024-10-03 02:13:54] debug: zh:ember:uart:ash: <-x- [FRAME type=DATA] Rejecting. 094221 [2024-10-03 02:13:57] debug: zh:ember:uart:ash: <--- [FRAME type=DATA] [2024-10-03 02:13:57] debug: zh:ember:uart:ash: <--- [FRAME type=DATA ackNum=1](ackRx=7 frmTx=7) [2024-10-03 02:13:57] debug: zh:ember:uart:ash: <-x- [FRAME type=DATA ackNum=1] Invalid ACK num; not within <7-7> [2024-10-03 02:13:57] debug: zh:ember:uart:ash: <-x- [FRAME type=DATA] Rejecting. 094221 [2024-10-03 02:14:00] debug: zh:ember:uart:ash: <--- [FRAME type=ERROR] [2024-10-03 02:14:00] error: zh:ember:uart:ash: Received ERROR from adapter, with code=ERROR_EXCEEDED_MAXIMUM_ACK_TIMEOUT_COUNT. [2024-10-03 02:14:00] error: zh:ember:uart:ash: ASH disconnected | Adapter status: ASH_NCP_FATAL_ERROR [2024-10-03 02:14:00] error: zh:ember:uart:ash: Error while parsing received frame, status=ASH_NCP_FATAL_ERROR. [2024-10-03 02:14:00] error: zh:ember: Adapter fatal error: HOST_FATAL_ERROR [2024-10-03 02:14:00] debug: zh:controller: Adapter disconnected [2024-10-03 02:14:00] info: zh:ember:uart:ash: ASH COUNTERS since last clear: [2024-10-03 02:14:00] info: zh:ember:uart:ash: Total frames: RX=50, TX=84 [2024-10-03 02:14:00] info: zh:ember:uart:ash: Cancelled : RX=0, TX=0 [2024-10-03 02:14:00] info: zh:ember:uart:ash: DATA frames : RX=45, TX=39 [2024-10-03 02:14:00] info: zh:ember:uart:ash: DATA bytes : RX=413, TX=437 [2024-10-03 02:14:00] info: zh:ember:uart:ash: Retry frames: RX=3, TX=0 [2024-10-03 02:14:00] info: zh:ember:uart:ash: ACK frames : RX=0, TX=43 [2024-10-03 02:14:00] info: zh:ember:uart:ash: NAK frames : RX=0, TX=1 [2024-10-03 02:14:00] info: zh:ember:uart:ash: nRdy frames : RX=0, TX=0 [2024-10-03 02:14:00] info: zh:ember:uart:ash: CRC errors : RX=0 [2024-10-03 02:14:00] info: zh:ember:uart:ash: Comm errors : RX=0 [2024-10-03 02:14:00] info: zh:ember:uart:ash: Length < minimum: RX=0 [2024-10-03 02:14:00] info: zh:ember:uart:ash: Length > maximum: RX=0 [2024-10-03 02:14:00] info: zh:ember:uart:ash: Bad controls : RX=0 [2024-10-03 02:14:00] info: zh:ember:uart:ash: Bad lengths : RX=0 [2024-10-03 02:14:00] info: zh:ember:uart:ash: Bad ACK numbers : RX=4 [2024-10-03 02:14:00] info: zh:ember:uart:ash: Out of buffers : RX=0 [2024-10-03 02:14:00] info: zh:ember:uart:ash: Retry dupes : RX=0 [2024-10-03 02:14:00] info: zh:ember:uart:ash: Out of sequence : RX=0 [2024-10-03 02:14:00] info: zh:ember:uart:ash: ACK timeouts : RX=0 [2024-10-03 02:14:00] info: zh:ember:uart:ash: Port closed. [2024-10-03 02:14:00] info: zh:ember:uart:ash: ======== ASH stopped ======== [2024-10-03 02:14:00] info: zh:ember:ezsp: ======== EZSP stopped ======== [2024-10-03 02:14:00] info: zh:ember: ======== Ember Adapter Stopped ======== [2024-10-03 02:14:00] error: z2m: Adapter disconnected, stopping [2024-10-03 02:14:00] debug: z2m: Saving state to file /app/data/state.json [2024-10-03 02:14:00] info: z2m:mqtt: MQTT publish: topic 'zigbee2mqtt/bridge/state', payload '{"state":"offline"}' [2024-10-03 02:14:00] info: z2m: Disconnecting from MQTT server [2024-10-03 02:14:00] info: z2m: Stopping zigbee-herdsman... [2024-10-03 02:14:00] debug: zh:controller:database: Writing database to '/app/data/database.db' [2024-10-03 02:14:00] info: z2m: Stopped zigbee-herdsman [2024-10-03 02:14:00] info: z2m: Stopped Zigbee2MQTT

SoulofAkuma avatar Oct 03 '24 01:10 SoulofAkuma

I have the same problem. I am using the ZBDONGLE-E with 7.4.4 original firmware. Using HA with Z2M on latest updates, I can't get the dongle to work. It always stops with the same error message, metionend above.

I have round about 100 devices in my network -- most of them are TUYA Zigbee devices. I have dimmers, presence detectors, heating controllers and blind controllers in every room.

Help would be appreciated. Kind regards ..

jan0o0sch avatar Oct 03 '24 06:10 jan0o0sch

I have original the Same Problem. But i only have 4 devices in z2m 2 motion detectors (tradfri and tuya) and 2 tuya switches . I am thankful for help.

Area-me avatar Oct 03 '24 19:10 Area-me

Same problem here too. It's not possible to make an update. It starts but failed after x seconds.

I have also a lot of this message: "zhc: Failed to apply calibration to 'pressure': 'pressure_calibration' is not a number, got string ()"

AURELB87 avatar Oct 04 '24 19:10 AURELB87

Seeing the same error when doing OTA updates, pairing new devices, and if I do several actions rapidly (pressing different buttons, toggling lights through the web interface, etc)

I've tried to eliminate potential causes through trial and error:

  • with a single IKEA styrbar switch in the network I was able to do an OTA update if the switch was directly on top of the dongle (took approximately 80 minutes). This could just have been luck
  • I could not do an OTA update from a few metres away with only a single device in the network
  • with 10+ devices in the network I have not been able to update a different switch even when it was directly on top. It fails after a few seconds, with 2-3 devices it gets to around 40% before failing
  • I've tried different combinations of devices in the network to eliminate a single device causing it
  • I've moved the dongle to different locations to keep it away from sources of interference, which has no effect
  • the issue seems to become more prevalent the larger the network grows. At 20 devices (6 of them are routers) it takes 4-5 attempts to pair a new device to the network. Distance to dongle/router doesn't seem to matter
  • I've tried with both 7.4.4 and 8.0.2 which didn't change the frequency of the error
  • Switching channels based on ember-zli scans had no effect. I do however live in an area with a lot of congestion in the 2.4ghz spectrum, so it could be that it's just too much noise on all possible channels
  • I didn't notice any difference in the error rate increasing the transmission power from 5 to 20, but I didn't do any metrics on this, so it could have made some difference

I used a deconz adapter until recently, but switched in an attempt to fix another bug (hue lights not updating their state when toggled in home assistant). I still had OTA issues with that, but pairing worked seamlessly

Scandiravian avatar Oct 23 '24 07:10 Scandiravian

This issue is stale because it has been open 180 days with no activity. Remove stale label or comment or this will be closed in 30 days

github-actions[bot] avatar Dec 23 '24 00:12 github-actions[bot]