search

home-assistant / core

:house_with_garden: Open source home automation that puts local control and privacy first.
https://www.home-assistant.io
Apache License 2.0
72.63k stars 30.4k forks source link

ZHA integration not working after updating core to 2020.12.0 #44239

Closed hrzlgnm closed 3 years ago

hrzlgnm commented 3 years ago

The problem

After the update to Home Assistant Core release 2020.12.0 all my previosly paired and working zigbee sensors (Xiaomi Aqara (LUMI weather)) went to unavailable. I tried to pair them again, it did not work at all, i had no log output in the pairing view.

Environment

Problem-relevant configuration.yaml

zha:
  zigpy_config:
    ezsp_config:
      CONFIG_APS_UNICAST_MESSAGE_COUNT: 12
      CONFIG_SOURCE_ROUTE_TABLE_SIZE: 16
      CONFIG_ADDRESS_TABLE_SIZE: 8

Traceback/Error logs

Additional information

After restoring the snapshot of Home Assistant Core 0.118.5, I was able to pair the sensors again and they started to work again, I even rebooted my raspberry pi4 with 4GB (64bit)

I'm using a ELELabs PI Shield as hardware https://elelabs.com/products/elelabs-zigbee-shield.html with the recommended NCP firmware update. I've updated the firmware to the V8 version and adjusted the config to the recommended settings for the V8 version respectively.

probot-home-assistant[bot] commented 3 years ago

Hey there @dmulcahey, @adminiuga, mind taking a look at this issue as its been labeled with an integration (zha) you are listed as a codeowner for? Thanks! (message by CodeOwnersMention)

Adminiuga commented 3 years ago

Do you have any other routers on the Zigbee network? Do those routers support Xiaomi devices?

Elelabs with v8 firmware from Elelabs will drop directly connected xiaomi devices. This is a known issue.

Debug logs of pairing? (see integration doc on how to enable debug logging)

hrzlgnm commented 3 years ago

I don't have any other routers on my zigbee network. Only 7 of those aqara LUMI lumi.weather sensors connected directly to the elelabs.

I already had logging enabled like suggested in the documentation

logger:
  default: info
  logs:
    homeassistant.core: debug
    homeassistant.components.zha: debug
    bellows.zigbee.application: debug
    bellows.ezsp: debug
    zigpy: debug
    zigpy_cc: debug
    zigpy_deconz.zigbee.application: debug
    zigpy_deconz.api: debug
    zigpy_xbee.zigbee.application: debug
    zigpy_xbee.api: debug
    zigpy_zigate: debug
    zigpy_znp: debug
    zhaquirks: debug

But clicking on 'show logs' during the pairing process with Home Assistant Core 2020.12.0 installed, showed no output. will try to install it once again and check if it happens once again. And collect debug logs.

After downgrading to 0.118.5, there was output in the logs during the pairing process and the pairing worked.

Would installing a v6 firmware to the Elelabs Device help here? Where are those known issues documented?

Adminiuga commented 3 years ago

yes, Either use V6 firmware or use https://github.com/zha-ng/EZSP-Firmware/blob/master/Elelabs-ELU013/efr32mg13p-v8-6820-115200.gbl firmware

With logging enabled, you should have a home-assistant.log file in the same folder where your configuration.yaml file is

hrzlgnm commented 3 years ago

Thanks! I will try out your linked firmware and report back if the problem still exists.

hrzlgnm commented 3 years ago

@Adminiuga, thanks a lot for the infos. I've updated the firwmare to https://github.com/zha-ng/EZSP-Firmware/blob/master/Elelabs-ELU013/efr32mg13p-v8-6820-115200.gbl and will report tomorrow.

Maybe it would be a good idea to refer to that firmware in the documentation, or at least add a note to not use the V8 from Elelabs?

hrzlgnm commented 3 years ago

This morning one of the sensors went offline again:

2020-12-15 05:19:02 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:15:8d:00:05:4b:9a:5b, unique_id=00:15:8d:00:05:4b:9a:5b, device_id=bbfc86128ea662d7852682e0e503c9af, device_event_type=device_offline>
2020-12-15 05:19:02 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.lumi_lumi_weather_humidity, old_state=<state sensor.lumi_lumi_weather_humidity=51.3; unit_of_measurement=%, friendly_name=Wohnzimmer humidity, device_class=humidity @ 2020-12-15T00:34:15.721904+01:00>, new_state=<state sensor.lumi_lumi_weather_humidity=unavailable; unit_of_measurement=%, friendly_name=Wohnzimmer humidity, device_class=humidity @ 2020-12-15T05:19:02.340765+01:00>>
2020-12-15 05:19:02 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.lumi_lumi_weather_temperature, old_state=<state sensor.lumi_lumi_weather_temperature=22.6; unit_of_measurement=°C, friendly_name=Wohnzimmer temperature, device_class=temperature @ 2020-12-15T00:34:15.723820+01:00>, new_state=<state sensor.lumi_lumi_weather_temperature=unavailable; unit_of_measurement=°C, friendly_name=Wohnzimmer temperature, device_class=temperature @ 2020-12-15T05:19:02.341351+01:00>>
2020-12-15 05:19:02 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.lumi_lumi_weather_power, old_state=<state sensor.lumi_lumi_weather_power=100; battery_size=CR2032, battery_quantity=1, battery_voltage=3.0, unit_of_measurement=%, friendly_name=Wohnzimmer power, device_class=battery @ 2020-12-15T00:34:15.725598+01:00>, new_state=<state sensor.lumi_lumi_weather_power=unavailable; unit_of_measurement=%, friendly_name=Wohnzimmer power, device_class=battery @ 2020-12-15T05:19:02.342000+01:00>>
2020-12-15 05:19:02 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.lumi_lumi_weather_pressure, old_state=<state sensor.lumi_lumi_weather_pressure=971; unit_of_measurement=hPa, friendly_name=Wohnzimmer pressure, device_class=pressure @ 2020-12-15T00:34:15.728362+01:00>, new_state=<state sensor.lumi_lumi_weather_pressure=unavailable; unit_of_measurement=hPa, friendly_name=Wohnzimmer pressure, device_class=pressure @ 2020-12-15T05:19:02.342464+01:00>>

pairing it again:

2020-12-15 08:06:13 DEBUG (MainThread) [bellows.ezsp.protocol] Send command permitJoining: (60,)
2020-12-15 08:06:13 DEBUG (MainThread) [bellows.ezsp.protocol] Send command addTransientLinkKey: (ff:ff:ff:ff:ff:ff:ff:ff, [90, 105, 103, 66, 101, 101, 65, 108, 108, 105, 97, 110, 99, 101, 48, 57])
2020-12-15 08:06:13 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'248321a9762a29c9147e'
2020-12-15 08:06:13 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4383a1a9762a15b6457e'
2020-12-15 08:06:13 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-12-15 08:06:13 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'358021a9fb2aea4da66bb5da55aac820fb0c42ceaca20be29ca800eccc47f2817e'
2020-12-15 08:06:13 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 34 (permitJoining) received: b'00'
2020-12-15 08:06:13 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5480a1a9fb2a152f917e'
2020-12-15 08:06:13 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-12-15 08:06:13 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 175 (addTransientLinkKey) received: b'00'
2020-12-15 08:06:13 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.memory_free, old_state=<state sensor.memory_free=2671.9; unit_of_measurement=MiB, friendly_name=Memory free, icon=mdi:memory @ 2020-12-15T08:05:13.342049+01:00>, new_state=<state sensor.memory_free=2671.5; unit_of_measurement=MiB, friendly_name=Memory free, icon=mdi:memory @ 2020-12-15T08:06:13.375897+01:00>>
2020-12-15 08:06:13 DEBUG (MainThread) [bellows.ezsp.protocol] Send command setPolicy: (<EzspPolicyId.TRUST_CENTER_POLICY: 0>, <EzspDecisionBitmask.ALLOW_UNSECURED_REJOINS|ALLOW_JOINS: 3>)
2020-12-15 08:06:13 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'468121a9012a15b15963eb7e'
2020-12-15 08:06:13 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6581a1a9012a15af4e7e'
2020-12-15 08:06:13 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-12-15 08:06:13 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 85 (setPolicy) received: b'00'
2020-12-15 08:06:13 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.processor_use, old_state=<state sensor.processor_use=6; unit_of_measurement=%, friendly_name=Processor use (percent), icon=mdi:cpu-64-bit @ 2020-12-15T08:05:13.352912+01:00>, new_state=<state sensor.processor_use=7; unit_of_measurement=%, friendly_name=Processor use (percent), icon=mdi:cpu-64-bit @ 2020-12-15T08:06:13.392449+01:00>>
2020-12-15 08:06:13 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.load_1m, old_state=<state sensor.load_1m=0.2; unit_of_measurement= , friendly_name=Load (1m), icon=mdi:cpu-64-bit @ 2020-12-15T08:05:43.357279+01:00>, new_state=<state sensor.load_1m=0.12; unit_of_measurement= , friendly_name=Load (1m), icon=mdi:cpu-64-bit @ 2020-12-15T08:06:13.398146+01:00>>
2020-12-15 08:06:13 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.load_5m, old_state=<state sensor.load_5m=0.34; unit_of_measurement= , friendly_name=Load (5m), icon=mdi:cpu-64-bit @ 2020-12-15T08:05:43.363553+01:00>, new_state=<state sensor.load_5m=0.3; unit_of_measurement= , friendly_name=Load (5m), icon=mdi:cpu-64-bit @ 2020-12-15T08:06:13.404198+01:00>>
2020-12-15 08:06:13 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.load_15m, old_state=<state sensor.load_15m=0.35; unit_of_measurement= , friendly_name=Load (15m), icon=mdi:cpu-64-bit @ 2020-12-15T08:05:43.369309+01:00>, new_state=<state sensor.load_15m=0.34; unit_of_measurement= , friendly_name=Load (15m), icon=mdi:cpu-64-bit @ 2020-12-15T08:06:13.410030+01:00>>
2020-12-15 08:06:14 DEBUG (MainThread) [bellows.ezsp.protocol] Send command readCounters: ()
2020-12-15 08:06:14 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'578621a9a52a5cc47e'
2020-12-15 08:06:14 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7686a1a9a52a15b2fd921524aa5592499c4e25abefce648affc66389fc7e3fa7ebcdde6f8fffc7dbd5d2698c4623a9ec763ba5ea758241984c2613b1e070381c0e07bbe5ca658a459a4d9e4f9ff7c3d9d46a35a251904824e4e37e'
2020-12-15 08:06:14 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-12-15 08:06:14 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 241 (readCounters) received: b'0000a4065f0100000000000002000200030102000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000'
2020-12-15 08:06:14 DEBUG (MainThread) [bellows.zigbee.application] EZSP Counters: COUNTER_MAC_RX_BROADCAST: 0,COUNTER_MAC_TX_BROADCAST: 1700,COUNTER_MAC_RX_UNICAST: 351,COUNTER_MAC_TX_UNICAST_SUCCESS: 0,COUNTER_MAC_TX_UNICAST_RETRY: 0,COUNTER_MAC_TX_UNICAST_FAILED: 0,COUNTER_APS_DATA_RX_BROADCAST: 2,COUNTER_APS_DATA_TX_BROADCAST: 2,COUNTER_APS_DATA_RX_UNICAST: 259,COUNTER_APS_DATA_TX_UNICAST_SUCCESS: 2,COUNTER_APS_DATA_TX_UNICAST_RETRY: 0,COUNTER_APS_DATA_TX_UNICAST_FAILED: 0,COUNTER_ROUTE_DISCOVERY_INITIATED: 0,COUNTER_NEIGHBOR_ADDED: 0,COUNTER_NEIGHBOR_REMOVED: 0,COUNTER_NEIGHBOR_STALE: 0,COUNTER_JOIN_INDICATION: 0,COUNTER_CHILD_REMOVED: 0,COUNTER_ASH_OVERFLOW_ERROR: 0,COUNTER_ASH_FRAMING_ERROR: 0,COUNTER_ASH_OVERRUN_ERROR: 0,COUNTER_NWK_FRAME_COUNTER_FAILURE: 0,COUNTER_APS_FRAME_COUNTER_FAILURE: 0,COUNTER_UTILITY: 0,COUNTER_APS_LINK_KEY_NOT_AUTHORIZED: 0,COUNTER_NWK_DECRYPTION_FAILURE: 0,COUNTER_APS_DECRYPTION_FAILURE: 0,COUNTER_ALLOCATE_PACKET_BUFFER_FAILURE: 0,COUNTER_RELAYED_UNICAST: 0,COUNTER_PHY_TO_MAC_QUEUE_LIMIT_REACHED: 0,COUNTER_PACKET_VALIDATE_LIBRARY_DROPPED_COUNT: 0,COUNTER_TYPE_NWK_RETRY_OVERFLOW: 0,COUNTER_PHY_CCA_FAIL_COUNT: 0,COUNTER_BROADCAST_TABLE_FULL: 0,COUNTER_PTA_LO_PRI_REQUESTED: 0,COUNTER_PTA_HI_PRI_REQUESTED: 0,COUNTER_PTA_LO_PRI_DENIED: 0,COUNTER_PTA_HI_PRI_DENIED: 0,COUNTER_PTA_LO_PRI_TX_ABORTED: 0,COUNTER_PTA_HI_PRI_TX_ABORTED: 0,COUNTER_ADDRESS_CONFLICT_SENT: 0
2020-12-15 08:06:24 DEBUG (MainThread) [bellows.ezsp.protocol] Send command readCounters: ()
2020-12-15 08:06:24 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'608721a9a52a7d31587e'
2020-12-15 08:06:24 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'0787a1a9a52a15b2fc921524aa5592499c4e25abefce648affc66389fc7e3fa7ebcdde6f8fffc7dbd5d2698c4623a9ec763ba5ea758241984c2613b1e070381c0e07bbe5ca658a459a4d9e4f9ff7c3d9d46a35a2519048243d827e'
2020-12-15 08:06:24 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8160597e'
2020-12-15 08:06:24 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 241 (readCounters) received: b'0000a5065f0100000000000002000200030102000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000'
2020-12-15 08:06:24 DEBUG (MainThread) [bellows.zigbee.application] EZSP Counters: COUNTER_MAC_RX_BROADCAST: 0,COUNTER_MAC_TX_BROADCAST: 1701,COUNTER_MAC_RX_UNICAST: 351,COUNTER_MAC_TX_UNICAST_SUCCESS: 0,COUNTER_MAC_TX_UNICAST_RETRY: 0,COUNTER_MAC_TX_UNICAST_FAILED: 0,COUNTER_APS_DATA_RX_BROADCAST: 2,COUNTER_APS_DATA_TX_BROADCAST: 2,COUNTER_APS_DATA_RX_UNICAST: 259,COUNTER_APS_DATA_TX_UNICAST_SUCCESS: 2,COUNTER_APS_DATA_TX_UNICAST_RETRY: 0,COUNTER_APS_DATA_TX_UNICAST_FAILED: 0,COUNTER_ROUTE_DISCOVERY_INITIATED: 0,COUNTER_NEIGHBOR_ADDED: 0,COUNTER_NEIGHBOR_REMOVED: 0,COUNTER_NEIGHBOR_STALE: 0,COUNTER_JOIN_INDICATION: 0,COUNTER_CHILD_REMOVED: 0,COUNTER_ASH_OVERFLOW_ERROR: 0,COUNTER_ASH_FRAMING_ERROR: 0,COUNTER_ASH_OVERRUN_ERROR: 0,COUNTER_NWK_FRAME_COUNTER_FAILURE: 0,COUNTER_APS_FRAME_COUNTER_FAILURE: 0,COUNTER_UTILITY: 0,COUNTER_APS_LINK_KEY_NOT_AUTHORIZED: 0,COUNTER_NWK_DECRYPTION_FAILURE: 0,COUNTER_APS_DECRYPTION_FAILURE: 0,COUNTER_ALLOCATE_PACKET_BUFFER_FAILURE: 0,COUNTER_RELAYED_UNICAST: 0,COUNTER_PHY_TO_MAC_QUEUE_LIMIT_REACHED: 0,COUNTER_PACKET_VALIDATE_LIBRARY_DROPPED_COUNT: 0,COUNTER_TYPE_NWK_RETRY_OVERFLOW: 0,COUNTER_PHY_CCA_FAIL_COUNT: 0,COUNTER_BROADCAST_TABLE_FULL: 0,COUNTER_PTA_LO_PRI_REQUESTED: 0,COUNTER_PTA_HI_PRI_REQUESTED: 0,COUNTER_PTA_LO_PRI_DENIED: 0,COUNTER_PTA_HI_PRI_DENIED: 0,COUNTER_PTA_LO_PRI_TX_ABORTED: 0,COUNTER_PTA_HI_PRI_TX_ABORTED: 0,COUNTER_ADDRESS_CONFLICT_SENT: 0
2020-12-15 08:06:28 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'1787b1a9772a15b3351311bfe15092c4894e23e7077e'
2020-12-15 08:06:28 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'82503a7e'
2020-12-15 08:06:28 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 35 (childJoinHandler) received: b'00016c875b9a4b05008d150004'
2020-12-15 08:06:28 DEBUG (MainThread) [bellows.zigbee.application] Received childJoinHandler frame with [0, <Bool.true: 1>, 0x876c, 00:15:8d:00:05:4b:9a:5b, <EmberNodeType.SLEEPY_END_DEVICE: 4>]
2020-12-15 08:06:29 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'2787b1a9702a7935020e0120aad887499d4e27ab51497e'
2020-12-15 08:06:29 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'83401b7e'
2020-12-15 08:06:29 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 36 (trustCenterJoinHandler) received: b'6c875b9a4b05008d150001000000'
2020-12-15 08:06:29 DEBUG (MainThread) [bellows.zigbee.application] Received trustCenterJoinHandler frame with [0x876c, 00:15:8d:00:05:4b:9a:5b, <EmberDeviceUpdate.STANDARD_SECURITY_UNSECURED_JOIN: 1>, <EmberJoinDecision.USE_PRECONFIGURED_KEY: 0>, 0x0000]
2020-12-15 08:06:29 INFO (MainThread) [zigpy.application] Device 0x876c (00:15:8d:00:05:4b:9a:5b) joined the network
2020-12-15 08:06:29 DEBUG (MainThread) [zigpy.application] Device 00:15:8d:00:05:4b:9a:5b changed id (0xec30 => 0x876c)
2020-12-15 08:06:29 DEBUG (MainThread) [bellows.ezsp.protocol] Send command findKeyTableEntry: (00:15:8d:00:05:4b:9a:5b, True)
2020-12-15 08:06:29 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'738421a9212a4e2812914aa8bf5593a82f7e'
2020-12-15 08:06:29 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'3084a1a9212aeae7497e'
2020-12-15 08:06:29 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8430fc7e'
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] device - 0x876c:00:15:8d:00:05:4b:9a:5b entering async_device_initialized - is_new_join: False
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] device - 0x876c:00:15:8d:00:05:4b:9a:5b has been reset and re-added or its nwk address changed
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] skipping discovery for previously discovered device - 0x876c:00:15:8d:00:05:4b:9a:5b
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x876c](lumi.weather): started configuration
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:ZDO](lumi.weather): 'async_configure' stage succeeded
2020-12-15 08:06:29 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 117 (findKeyTableEntry) received: b'ff'
2020-12-15 08:06:29 INFO (Thread-5) [aiosqlite] returning exception UNIQUE constraint failed: devices.ieee
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:1:0x0000]: skipping channel configuration
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:1:0x0405]: skipping channel configuration
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:1:0x0402]: skipping channel configuration
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:1:0x0001]: skipping channel configuration
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:1:0x0403]: skipping channel configuration
2020-12-15 08:06:29 DEBUG (MainThread) [zigpy.appdb] Device 00:15:8d:00:05:4b:9a:5b already exists. Updating it.
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:1:0x0000]: 'async_configure' stage succeeded
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:1:0x0405]: 'async_configure' stage succeeded
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:1:0x0402]: 'async_configure' stage succeeded
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:1:0x0001]: 'async_configure' stage succeeded
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:1:0x0403]: 'async_configure' stage succeeded
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x876c](lumi.weather): completed configuration
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x876c](lumi.weather): stored in registry: ZhaDeviceEntry(name='LUMI lumi.weather', ieee='00:15:8d:00:05:4b:9a:5b', last_seen=1607984299.2561371)
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x876c](lumi.weather): started initialization
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:ZDO](lumi.weather): 'async_initialize' stage succeeded
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.lumi_lumi_weather_power, old_state=<state sensor.lumi_lumi_weather_power=unavailable; unit_of_measurement=%, friendly_name=Wohnzimmer power, device_class=battery @ 2020-12-15T05:19:02.342000+01:00>, new_state=<state sensor.lumi_lumi_weather_power=100; battery_size=CR2032, battery_quantity=1, battery_voltage=3.0, unit_of_measurement=%, friendly_name=Wohnzimmer power, device_class=battery @ 2020-12-15T08:06:29.325304+01:00>>
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:1:0x0000]: 'async_initialize' stage succeeded
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:1:0x0405]: 'async_initialize' stage succeeded
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:1:0x0402]: 'async_initialize' stage succeeded
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:1:0x0001]: 'async_initialize' stage succeeded
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x876c:1:0x0403]: 'async_initialize' stage succeeded
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x876c](lumi.weather): power source: Battery or Unknown
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x876c](lumi.weather): completed initialization
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.lumi_lumi_weather_humidity, old_state=<state sensor.lumi_lumi_weather_humidity=unavailable; unit_of_measurement=%, friendly_name=Wohnzimmer humidity, device_class=humidity @ 2020-12-15T05:19:02.340765+01:00>, new_state=<state sensor.lumi_lumi_weather_humidity=51.3; unit_of_measurement=%, friendly_name=Wohnzimmer humidity, device_class=humidity @ 2020-12-15T08:06:29.334794+01:00>>
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.lumi_lumi_weather_temperature, old_state=<state sensor.lumi_lumi_weather_temperature=unavailable; unit_of_measurement=°C, friendly_name=Wohnzimmer temperature, device_class=temperature @ 2020-12-15T05:19:02.341351+01:00>, new_state=<state sensor.lumi_lumi_weather_temperature=22.6; unit_of_measurement=°C, friendly_name=Wohnzimmer temperature, device_class=temperature @ 2020-12-15T08:06:29.335175+01:00>>
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event state_changed[L]: entity_id=sensor.lumi_lumi_weather_pressure, old_state=<state sensor.lumi_lumi_weather_pressure=unavailable; unit_of_measurement=hPa, friendly_name=Wohnzimmer pressure, device_class=pressure @ 2020-12-15T05:19:02.342464+01:00>, new_state=<state sensor.lumi_lumi_weather_pressure=971; unit_of_measurement=hPa, friendly_name=Wohnzimmer pressure, device_class=pressure @ 2020-12-15T08:06:29.335604+01:00>>
2020-12-15 08:06:29 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'4084b1a9112a11b259874a25aa5593499cb5df7181499874f1c20f0ea7e474a2eb40cb6f0ffd14547e'
2020-12-15 08:06:29 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8520dd7e'
2020-12-15 08:06:29 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0400001300000000010000fbf8da6c87ffff0c046c875b9a4b05008d15008002'
2020-12-15 08:06:29 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_BROADCAST: 4>, EmberApsFrame(profileId=0, clusterId=19, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=251), 248, -38, 0x876c, 255, 255, b'\x04l\x87[\x9aK\x05\x00\x8d\x15\x00\x80']
2020-12-15 08:06:29 INFO (MainThread) [bellows.zigbee.application] ZDO Device announce: 0x876c, 00:15:8d:00:05:4b:9a:5b
2020-12-15 08:06:29 INFO (MainThread) [zigpy.application] Device 0x876c (00:15:8d:00:05:4b:9a:5b) joined the network
2020-12-15 08:06:29 DEBUG (MainThread) [zigpy.application] Skip initialization for existing device 00:15:8d:00:05:4b:9a:5b
2020-12-15 08:06:29 DEBUG (MainThread) [zigpy.zdo] [0x876c:zdo] ZDO request ZDOCmd.Device_annce: [0x876C, 00:15:8d:00:05:4b:9a:5b, 128]
2020-12-15 08:06:29 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'5084b1a9112a15b658944a24ab5593499cb2df7181499874eade6383f97e7dab87b8b306a188a2baa1ba0cfe472389e97477397e'
2020-12-15 08:06:29 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8610be7e'
2020-12-15 08:06:29 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0004010000010100010000fcf8da6c87ffff1718000a0500420c6c756d692e776561746865720100200502'
2020-12-15 08:06:29 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=252), 248, -38, 0x876c, 255, 255, b'\x18\x00\n\x05\x00B\x0clumi.weather\x01\x00 \x05']
2020-12-15 08:06:29 DEBUG (MainThread) [zigpy.zcl] [0x876c:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=0 command_id=Command.Report_Attributes>
2020-12-15 08:06:29 DEBUG (MainThread) [zigpy.zcl] [0x876c:1:0x0000] ZCL request 0x000a: [[Attribute(attrid=5, value=<TypeValue type=CharacterString, value=lumi.weather>), Attribute(attrid=1, value=<TypeValue type=uint8_t, value=5>)]]
2020-12-15 08:06:29 DEBUG (MainThread) [zigpy.zcl] [0x876c:1:0x0000] Attribute report received: model=lumi.weather, app_version=5
2020-12-15 08:06:29 DEBUG (MainThread) [homeassistant.core] Bus:Handling <Event zha_event[L]: device_ieee=00:15:8d:00:05:4b:9a:5b, unique_id=00:15:8d:00:05:4b:9a:5b:1:0x0000, device_id=bbfc86128ea662d7852682e0e503c9af, endpoint_id=1, cluster_id=0, command=attribute_updated, args=attribute_id=5, attribute_name=model, value=lumi.weather>
2020-12-15 08:06:30 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'6084b1a96b2a134fa6944a36aa5592499d4e275012ce67bbc27e'
2020-12-15 08:06:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'87009f7e'
2020-12-15 08:06:30 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 63 (messageSentHandler) received: b'06fdff00001300000000010000fbff0000'
2020-12-15 08:06:30 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_BROADCAST: 6>, 65533, EmberApsFrame(profileId=0, clusterId=19, sourceEndpoint=0, destinationEndpoint=0, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=251), 255, <EmberStatus.SUCCESS: 0>, b'']
2020-12-15 08:06:30 DEBUG (MainThread) [bellows.zigbee.application] Unexpected message send notification tag: 255
2020-12-15 08:06:30 DEBUG (bellows.thread_0) [bellows.uart] Data frame: b'7084b1a9112a15b658944a24ab5593499cb3cf7d81499874d1de6283fd817d82eaecd3638bde6fdad0f37d8c4007a8ec763ba58e5c6549fd6dc833d7cb47431d0e0d9ae5ca6789067e'
2020-12-15 08:06:30 DEBUG (bellows.thread_0) [bellows.uart] Sending: b'8070787e'
2020-12-15 08:06:30 DEBUG (MainThread) [bellows.ezsp.protocol] Application frame 69 (incomingMessageHandler) received: b'0004010000010100010000fde8d66c87ffff2c18010a01ff422501210d0c0421a80105211400062401000000006429e7086521ee20662b377b01000a21000002'
2020-12-15 08:06:30 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, EmberApsFrame(profileId=260, clusterId=0, sourceEndpoint=1, destinationEndpoint=1, options=<EmberApsOption.APS_OPTION_ENABLE_ROUTE_DISCOVERY: 256>, groupId=0, sequence=253), 232, -42, 0x876c, 255, 255, b'\x18\x01\n\x01\xffB%\x01!\r\x0c\x04!\xa8\x01\x05!\x14\x00\x06$\x01\x00\x00\x00\x00d)\xe7\x08e!\xee f+7{\x01\x00\n!\x00\x00']
2020-12-15 08:06:30 DEBUG (MainThread) [zigpy.zcl] [0x876c:1:0x0000] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=True> manufacturer=None tsn=1 command_id=Command.Report_Attributes>
2020-12-15 08:06:30 DEBUG (MainThread) [zigpy.zcl] [0x876c:1:0x0000] ZCL request 0x000a: [[Attribute(attrid=65281, value=<TypeValue type=CharacterString, value=!

I will wait for another 24h and see if any issues arise. @Adminiuga on that firmware page you linked, it suggests other config settings for the ezsp, are mine correct or do i need to adjust them?

zha:
  zigpy_config:
    ezsp_config:
      CONFIG_APS_UNICAST_MESSAGE_COUNT: 12
      CONFIG_SOURCE_ROUTE_TABLE_SIZE: 16
      CONFIG_ADDRESS_TABLE_SIZE: 8

vs

Configuration Parameter Value
Address Table Size 16
Child Table Size 32
Source Routes 200
giannello commented 3 years ago

There seems to be many different sources for the right parameters to use with bellows. I'm also on an Elelabs Shield, and my config doesn't override any parameter:

zha:
  zigpy_config:
    ota:
      ikea_provider: true
      ledvance_provider: true
    source_routing: true

The system works fine with all the latest updates, and the Aqara sensors are stable on the network.

dmulcahey commented 3 years ago

The parameters are really network specific... larger networks do better with different settings etc... YMMV

shackrat commented 3 years ago

Generally speaking, CONFIG_ADDRESS_TABLE_SIZE should be matched to CONFIG_SOURCE_ROUTE_TABLE_SIZE as long as the coordinator and stack allows for values that large. I have a few more devices left to connect so I set the table size higher to accommodate the future growth.

For anyone wondering, I have a 204 node Zigbee network using a HUSBZB-1 stick. These are my settings...

zha:
  zigpy_config:
    source_routing: true
    ezsp_config:
        CONFIG_SOURCE_ROUTE_TABLE_SIZE: 230
        CONFIG_NEIGHBOR_TABLE_SIZE: 16
        CONFIG_MAX_END_DEVICE_CHILDREN: 6
        CONFIG_APS_UNICAST_MESSAGE_COUNT: 32
        CONFIG_BINDING_TABLE_SIZE: 32
        CONFIG_ADDRESS_TABLE_SIZE: 230
        CONFIG_ROUTE_TABLE_SIZE: 32
        CONFIG_BROADCAST_TABLE_SIZE: 32
        CONFIG_TRUST_CENTER_ADDRESS_CACHE_SIZE: 4
        CONFIG_MTORR_FLOW_CONTROL: 1
Adminiuga commented 3 years ago

Generally speaking, CONFIG_ADDRESS_TABLE_SIZE should be matched to CONFIG_SOURCE_ROUTE_TABLE_SIZE

What's your source?

Adminiuga commented 3 years ago

CONFIG_ADDRESS_TABLE_SIZE = The maximum number of EUI64 to network address associations that the stack can maintain for the application. Zigbee does not use EUI64 addresses for every or most of operation.

For anyone wondering, I have a 204 node Zigbee network using a HUSBZB-1 stick. These are my settings...

You may think so, but I believe HUSBZB with original firmware just discards the settings which don't fit into the range. And nobody knows with what settings the HUSBZB firmware was built. One of KB articles specifically mentioned that it is app to the host app to make sure the parameters are within the range, and ncp image does not do any validation, because of the memory size constraints.

hrzlgnm commented 3 years ago

Wow, thank you guys for all your feedback. I will go with default settings as far as everything works out, like @giannello suggested..

Currently everything is working fine and the connection to the lumi.wheather sensors is stable now.

I should have looked through the closed issues, this one seems to be a duplicate of #43237. My bad.

Thank you all for your feedback regarding the issue, it actually helped me solving it.

shackrat commented 3 years ago

CONFIG_ADDRESS_TABLE_SIZE = The maximum number of EUI64 to network address associations that the stack can maintain for the application. Zigbee does not use EUI64 addresses for every or most of operation.

I might be wrong in my understanding, but I've always believed that EUI64 addresses were based on the devices MAC address. I do recall reading that in SiLabs docs at one point. If so it makes sense to maintain that table, if the concentrator allows for it.

I've flashed 6.6.5 onto the HUSBZB-1 and I can confirm by log analysis that the source route table size does work being that large, as evidenced by the lack of route discovery in the logs. I can't validate the address table size specifically because bellows does not provide that feedback.

Adminiuga commented 3 years ago

Zigbee network (and most of the stacks) use NWK uint16 addressing. EUI64 addressing is used only when NWK address is not known.

Adminiuga commented 3 years ago

in other words, allocating too many addresses just wastes memory without any benefit. And HUSBZB-1 doesn't have too much memory to begin with.

Adminiuga commented 3 years ago

I might be wrong in my understanding, but I've always believed that EUI64 addresses were based on the devices MAC address. I do recall reading that in SiLabs docs at one point.

That's correct. EUI64 is the IEEE/MAC address of the device

If so it makes sense to maintain that table, if the concentrator allows for it.

This part is incorrect. As Zigbee stacks prefer using NWK addressing vs addressing devices by their IEEE addresses.

giannello commented 3 years ago

@hrzlgnm FYI the default settings work fine for me with both the Elelabs v8 firmware and the latest zha-ng firmware (6.8.2.0).