core: ZHA Does Not Remember New Paired Device Across Core Restarts

The problem

I have been running ZHA integration with a Digi XBee coordinator, paired with a number of smart light bulbs, with no issues and not adding any new devices for a very long time (literally years). I got a new device (IKEA 5-button remote e1810) the other day and added it to my installation using the UI based pairing method, with no problems. Then I noticed that after a core restart of HA the remote was unavailable. Querying with sqlite3, I found that the remote had never been properly registered in the /config/zigbee.db. The remote is properly registered in both /config/.storage/core.device_registry and /config/.storage/zha.storage. Not sure how to troubleshoot this further, I completely deleted the entire ZHA integration in my configuration and started from scratch to set it up and re-pair all my existing devices. After pairing each one, everything appeared to be working, but I found that when I restarted HA core again, they were all unavailable. Checking the newly created /config/zigbee.db again with sqlite3, I found that no devices have been registered there at all. It seems that the zigbee.db has only been created empty and remains empty after numerous devices are paired. At this point I’m recovering the old configuration from snapshots to try to get back to working zigbee.

Environment

• Home Assistant Core release with the issue:

Version | 2021.1.1 Installation Type | Home Assistant Supervised Development | false Supervisor | true Docker | true Virtual Environment | false Python Version | 3.8.7 Operating System Family | Linux Operating System Version | 5.9.0-0.bpo.2-arm64 CPU Architecture | aarch64 Timezone | America/Detroit

• Last working Home Assistant Core release (if known): Unknown
• Integration causing this issue: ZHA
• Link to integration documentation on our website: https://www.home-assistant.io/integrations/zha/

Problem-relevant configuration.yaml

Integration configured by UI only

Traceback/Error logs

This is a log of pairing one of he bulbs.

2021-01-12 16:50:30 DEBUG (MainThread) [zigpy_xbee.zigbee.application] Broadcast request seq 1
2021-01-12 16:50:30 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (00:00:00:00:00:00:ff:fc, <BroadcastAddress.ALL_ROUTERS_AND_COORDINATOR: 65532>, 0, 0, 54, 0, 0, 0, b'\x01<\x00')
2021-01-12 16:50:30 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x11\x11\x00\x00\x00\x00\x00\x00\xff\xfc\xff\xfc\x00\x00\x006\x00\x00\x00\x00\x01<\x00'
2021-01-12 16:50:31 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b\x11\xff\xfe\x00&\x00'
2021-01-12 16:50:31 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2021-01-12 16:50:31 DEBUG (MainThread) [zigpy_xbee.api] tx_explicit to 0xfffe: TXStatus.BROADCAST_RELAY_FAILURE after 0 tries. Discovery Status: DiscoveryStatus.SUCCESS, Frame #17
2021-01-12 16:50:31 ERROR (MainThread) [homeassistant.components.websocket_api.http.connection] [281472768004640] Error handling message: Unknown error
Traceback (most recent call last):
  File "/usr/src/homeassistant/homeassistant/components/websocket_api/decorators.py", line 18, in _handle_async_response
    await func(hass, connection, msg)
  File "/usr/src/homeassistant/homeassistant/components/zha/api.py", line 230, in websocket_permit_devices
    await zha_gateway.application_controller.permit(time_s=duration, node=ieee)
  File "/usr/local/lib/python3.8/site-packages/zigpy/application.py", line 370, in permit
    await zigpy.zdo.broadcast(
  File "/usr/local/lib/python3.8/site-packages/zigpy/device.py", line 400, in broadcast
    result = await app.broadcast(
  File "/usr/local/lib/python3.8/site-packages/zigpy_xbee/zigbee/application.py", line 359, in broadcast
    v = await asyncio.wait_for(request, timeout=TIMEOUT_TX_STATUS)
  File "/usr/local/lib/python3.8/asyncio/tasks.py", line 494, in wait_for
    return fut.result()
zigpy.exceptions.DeliveryError: TXStatus.BROADCAST_RELAY_FAILURE
2021-01-12 16:51:01 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\xf0\xd1\xb8\x00\x00\x04\xae,\x10$\x00\x00\x00\x13\x00\x00\x02\x81$\x10,\xae\x04\x00\x00\xb8\xd1\xf0\x8e'
2021-01-12 16:51:01 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2021-01-12 16:51:01 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (f0:d1:b8:00:00:04:ae:2c, 0x1024, 0, 19, 2, b'8124102cae040000b8d1f08e')
2021-01-12 16:51:01 INFO (MainThread) [zigpy_xbee.zigbee.application] New device joined: NWK 0x1024, IEEE f0:d1:b8:00:00:04:ae:2c
2021-01-12 16:51:01 INFO (MainThread) [zigpy.application] Device 0x1024 (f0:d1:b8:00:00:04:ae:2c) joined the network
2021-01-12 16:51:01 DEBUG (MainThread) [zigpy.zdo] [0x1024:zdo] ZDO request ZDOCmd.Device_annce: [0x1024, f0:d1:b8:00:00:04:ae:2c, 142]
2021-01-12 16:51:01 INFO (MainThread) [zigpy.device] [0x1024] Requesting 'Node Descriptor'
2021-01-12 16:51:01 DEBUG (MainThread) [zigpy.util] Tries remaining: 2
2021-01-12 16:51:01 DEBUG (MainThread) [zigpy.device] [0x1024] Extending timeout for 0x02 request
2021-01-12 16:51:01 DEBUG (MainThread) [zigpy_xbee.zigbee.application] Zigbee request tsn #2: b'022410'
2021-01-12 16:51:01 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (f0:d1:b8:00:00:04:ae:2c, 0x1024, 0, 0, <ZDOCmd.Node_Desc_req: 0x0002>, 0, 0, 64, b'\x02$\x10')
2021-01-12 16:51:01 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x11\x12\xf0\xd1\xb8\x00\x00\x04\xae,\x10$\x00\x00\x00\x02\x00\x00\x00@\x02$\x10'
2021-01-12 16:51:09 WARNING (MainThread) [homeassistant.components.cloud.google_config] Error reporting state - 5: Requested entity was not found.
2021-01-12 16:52:45 DEBUG (MainThread) [zigpy_xbee.zigbee.application] Broadcast request seq 24
2021-01-12 16:52:45 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (00:00:00:00:00:00:ff:fc, <BroadcastAddress.ALL_ROUTERS_AND_COORDINATOR: 65532>, 0, 0, 54, 0, 0, 0, b'\x18<\x00')
2021-01-12 16:52:45 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x11,\x00\x00\x00\x00\x00\x00\xff\xfc\xff\xfc\x00\x00\x006\x00\x00\x00\x00\x18<\x00'
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\xf0\xd1\xb8\x00\x00\x04\xae,\x10$\x01\x01\x00\x06\x01\x04\x01\x08\x00\n\x00\x00\x10\x01'
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (f0:d1:b8:00:00:04:ae:2c, 0x1024, 1, 6, 1, b'08000a00001001')
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy.zcl] [0x1024:1:0x0006] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=0 command_id=Command.Report_Attributes>
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy.zcl] [0x1024:1:0x0006] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=Bool, value=Bool.true>)]]
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy.zcl] [0x1024:1:0x0006] Attribute report received: on_off=1
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.zigbee.application] Zigbee request tsn #0: b'18000b0a00'
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (f0:d1:b8:00:00:04:ae:2c, 0x1024, 1, 1, 6, 260, 0, 0, b'\x18\x00\x0b\n\x00')
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x11-\xf0\xd1\xb8\x00\x00\x04\xae,\x10$\x01\x01\x00\x06\x01\x04\x00\x00\x18\x00\x0b\n\x00'
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b,\xff\xfe\x00\x00\x00'
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] tx_explicit to 0xfffe: TXStatus.SUCCESS after 0 tries. Discovery Status: DiscoveryStatus.SUCCESS, Frame #44
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] at command: NJ (60,)
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'NJ', b'<')
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08.NJ<'
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88.NJ\x00'
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] at command: AC ()
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'AC', b'')
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x08/AC'
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x88/AC\x00'
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] at command: CB (2,)
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] Command at (b'CB', b'\x02')
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x080CB\x02'
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x880CB\x00'
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] Frame received: at_response
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\xf0\xd1\xb8\x00\x00\x04\xae,\x10$\x01\x01\x00\x08\x01\x04\x01\x08\x01\n\x00\x00 \xfe'
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (f0:d1:b8:00:00:04:ae:2c, 0x1024, 1, 8, 1, b'08010a000020fe')
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy.zcl] [0x1024:1:0x0008] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=1 command_id=Command.Report_Attributes>
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy.zcl] [0x1024:1:0x0008] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint8_t, value=254>)]]
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy.zcl] [0x1024:1:0x0008] Attribute report received: current_level=254
2021-01-12 16:52:46 DEBUG (MainThread) [homeassistant.components.zha.core.channels.base] [0x1024:1:0x0008]: received attribute: 0 update with value: 254
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.zigbee.application] Zigbee request tsn #1: b'18010b0a00'
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (f0:d1:b8:00:00:04:ae:2c, 0x1024, 1, 1, 8, 260, 0, 0, b'\x18\x01\x0b\n\x00')
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x111\xf0\xd1\xb8\x00\x00\x04\xae,\x10$\x01\x01\x00\x08\x01\x04\x00\x00\x18\x01\x0b\n\x00'
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b-\x10$\x08\x00\x00'
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] tx_explicit to 0x1024: TXStatus.SUCCESS after 8 tries. Discovery Status: DiscoveryStatus.SUCCESS, Frame #45
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b1\x10$\x00\x00\x00'
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2021-01-12 16:52:46 DEBUG (MainThread) [zigpy_xbee.api] tx_explicit to 0x1024: TXStatus.SUCCESS after 0 tries. Discovery Status: DiscoveryStatus.SUCCESS, Frame #49
2021-01-12 16:52:52 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\xf0\xd1\xb8\x00\x00\x04\xae,\x10$\x00\x00\x00\x13\x00\x00\x02\x81$\x10,\xae\x04\x00\x00\xb8\xd1\xf0\x8e'
2021-01-12 16:52:52 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2021-01-12 16:52:52 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (f0:d1:b8:00:00:04:ae:2c, 0x1024, 0, 19, 2, b'8124102cae040000b8d1f08e')
2021-01-12 16:52:52 INFO (MainThread) [zigpy_xbee.zigbee.application] New device joined: NWK 0x1024, IEEE f0:d1:b8:00:00:04:ae:2c
2021-01-12 16:52:52 INFO (MainThread) [zigpy.application] Device 0x1024 (f0:d1:b8:00:00:04:ae:2c) joined the network
2021-01-12 16:52:52 DEBUG (MainThread) [zigpy.application] Skip initialization for existing device f0:d1:b8:00:00:04:ae:2c
2021-01-12 16:52:52 DEBUG (MainThread) [zigpy.zdo] [0x1024:zdo] ZDO request ZDOCmd.Device_annce: [0x1024, f0:d1:b8:00:00:04:ae:2c, 142]
2021-01-12 16:52:52 DEBUG (MainThread) [zigpy_xbee.zigbee.application] Zigbee request tsn #25: b'01190200'
2021-01-12 16:52:52 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (f0:d1:b8:00:00:04:ae:2c, 0x1024, 1, 1, 4, 260, 0, 0, b'\x01\x19\x02\x00')
2021-01-12 16:52:52 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x112\xf0\xd1\xb8\x00\x00\x04\xae,\x10$\x01\x01\x00\x04\x01\x04\x00\x00\x01\x19\x02\x00'
2021-01-12 16:52:53 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\xf0\xd1\xb8\x00\x00\x04\xae,\x10$\x01\x01\x00\x04\x01\x04\x01\x19\x19\x02\xff\x00'
2021-01-12 16:52:53 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2021-01-12 16:52:53 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (f0:d1:b8:00:00:04:ae:2c, 0x1024, 1, 4, 1, b'191902ff00')
2021-01-12 16:52:53 DEBUG (MainThread) [zigpy.zcl] [0x1024:1:0x0004] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=CLUSTER_COMMAND manufacturer_specific=False is_reply=True disable_default_response=True> manufacturer=None tsn=25 command_id=2>
2021-01-12 16:52:53 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b2\x10$\x00\x00\x00'
2021-01-12 16:52:53 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2021-01-12 16:52:53 DEBUG (MainThread) [zigpy_xbee.api] tx_explicit to 0x1024: TXStatus.SUCCESS after 0 tries. Discovery Status: DiscoveryStatus.SUCCESS, Frame #50
2021-01-12 16:53:13 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x91\xf0\xd1\xb8\x00\x00\x04\xae,\x10$\x01\x01\x03\x00\x01\x04\x01\x08\x04\n\x00\x00 \x00\x01\x00 \xfe\x03\x00!ka\x04\x00!}`\x07\x00!r\x01'
2021-01-12 16:53:13 DEBUG (MainThread) [zigpy_xbee.api] Frame received: explicit_rx_indicator
2021-01-12 16:53:13 DEBUG (MainThread) [zigpy_xbee.api] _handle_explicit_rx: (f0:d1:b8:00:00:04:ae:2c, 0x1024, 1, 768, 1, b'08040a00002000010020fe0300216b610400217d600700217201')
2021-01-12 16:53:13 DEBUG (MainThread) [zigpy.zcl] [0x1024:1:0x0300] ZCL deserialize: <ZCLHeader frame_control=<FrameControl frame_type=GLOBAL_COMMAND manufacturer_specific=False is_reply=False disable_default_response=False> manufacturer=None tsn=4 command_id=Command.Report_Attributes>
2021-01-12 16:53:13 DEBUG (MainThread) [zigpy.zcl] [0x1024:1:0x0300] ZCL request 0x000a: [[Attribute(attrid=0, value=<TypeValue type=uint8_t, value=0>), Attribute(attrid=1, value=<TypeValue type=uint8_t, value=254>), Attribute(attrid=3, value=<TypeValue type=uint16_t, value=24939>), Attribute(attrid=4, value=<TypeValue type=uint16_t, value=24701>), Attribute(attrid=7, value=<TypeValue type=uint16_t, value=370>)]]
2021-01-12 16:53:13 DEBUG (MainThread) [zigpy.zcl] [0x1024:1:0x0300] Attribute report received: current_hue=0, current_saturation=254, current_x=24939, current_y=24701, color_temperature=370
2021-01-12 16:53:13 DEBUG (MainThread) [zigpy_xbee.zigbee.application] Zigbee request tsn #4: b'18040b0a00'
2021-01-12 16:53:13 DEBUG (MainThread) [zigpy_xbee.api] Command tx_explicit (f0:d1:b8:00:00:04:ae:2c, 0x1024, 1, 1, 768, 260, 0, 0, b'\x18\x04\x0b\n\x00')
2021-01-12 16:53:13 DEBUG (MainThread) [zigpy_xbee.uart] Sending: b'\x113\xf0\xd1\xb8\x00\x00\x04\xae,\x10$\x01\x01\x03\x00\x01\x04\x00\x00\x18\x04\x0b\n\x00'
2021-01-12 16:53:13 DEBUG (MainThread) [zigpy_xbee.uart] Frame received: b'\x8b3\x10$\x00\x00\x00'
2021-01-12 16:53:13 DEBUG (MainThread) [zigpy_xbee.api] Frame received: tx_status
2021-01-12 16:53:13 DEBUG (MainThread) [zigpy_xbee.api] tx_explicit to 0x1024: TXStatus.SUCCESS after 0 tries. Discovery Status: DiscoveryStatus.SUCCESS, Frame #51

Additional information