search

zigpy / bellows

A Python 3 project to implement EZSP for EmberZNet devices
GNU General Public License v3.0
179 stars 87 forks source link

Failed ZDO request during device initialization - on each startup #207

Closed shortbloke closed 4 years ago

shortbloke commented 4 years ago

Whenever I start/re-start my Home Assistant (0.103.6) instance (not sure how to determine what versions of zigpy is included), I'm seeing an error logged: ERROR (MainThread) [zigpy.device] Failed ZDO request during device initialization

This is using a Nortek HUSBZB-1 USB Zigbee transceiver.

With debug logging enabled, the device which appears to be causing the error is Device 0x0000 (00:0d:6f:00:0b:5d:d1:25) joined the network Though I don't see that device in the zigbee database. Any suggestions on what might be going on here and how to fix/avoid the error?

Debug Logs

2020-01-14 14:49:39 DEBUG (MainThread) [bellows.zigbee.application] APS_UNICAST_MESSAGE_COUNT is set to 10
2020-01-14 14:49:39 DEBUG (MainThread) [bellows.zigbee.application] Ezsp adding endpoint: [<EzspStatus.SUCCESS: 0>]
2020-01-14 14:49:40 INFO (MainThread) [zigpy.application] Device 0x0000 (00:0d:6f:00:0b:5d:d1:25) joined the network
2020-01-14 14:49:40 DEBUG (MainThread) [bellows.zigbee.application] EZSP nwk=0x0000, IEEE=00:0d:6f:00:0b:5d:d1:25
2020-01-14 14:49:40 DEBUG (MainThread) [bellows.zigbee.application] Starting EZSP watchdog
2020-01-14 14:49:40 INFO (MainThread) [zigpy.device] [0x0000] Requesting 'Node Descriptor'
2020-01-14 14:49:40 DEBUG (MainThread) [zigpy.device] [0x0000] Extending timeout for 0x01 request
2020-01-14 14:49:40 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 00:0d:6f:00:0b:5d:d1:25/0x0000
2020-01-14 14:49:40 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=0 clusterId=2 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=211>, 255, 0, 0x0000, 255, 255, b'\x01\x00\x00']
2020-01-14 14:49:40 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request 0x0002: [0x0000]
2020-01-14 14:49:40 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] Unsupported ZDO request:0x0002
2020-01-14 14:49:40 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=0 clusterId=32770 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=212>, 255, 0, 0x0000, 255, 255, b'\x01\x00\x00\x00\x00@\x8f\xcd\xabR\x80\x00\x00\x00\x80\x00\x00']
2020-01-14 14:49:40 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request 0x8002: [<Status.SUCCESS: 0>, 0x0000, <Optional byte1=0 byte2=64 mac_capability_flags=143 manufacturer_code=43981 maximum_buffer_size=82 maximum_incoming_transfer_size=128 server_mask=0 maximum_outgoing_transfer_size=128 descriptor_capability_field=0>]
2020-01-14 14:49:40 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] Unsupported ZDO request:0x8002
2020-01-14 14:49:40 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0, <EmberApsFrame profileId=0 clusterId=2 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=211>, 2, <EmberStatus.SUCCESS: 0>, b'']
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xbd85](lumi.sensor_magnet.aq2): started initialization
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xbd85:ZDO](lumi.sensor_magnet.aq2): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.sensor_magnet.aq2', ieee='00:15:8d:00:03:67:3f:64', last_seen=1579008703.6866663)
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xbd85:ZDO](lumi.sensor_magnet.aq2): channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x1049](lumi.sensor_magnet.aq2): started initialization
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x1049:ZDO](lumi.sensor_magnet.aq2): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.sensor_magnet.aq2', ieee='00:15:8d:00:02:75:33:5b', last_seen=1579012988.7722054)
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x1049:ZDO](lumi.sensor_magnet.aq2): channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xbd85:1:0x0000]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xbd85:1:0x0000]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xbd85:1:0x0001]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xbd85:1:0x0001]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xbd85:1:0x0006]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xbd85:1:0x0006]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xbd85:1:0x0006]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xbd85:1:0x0006]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x1049:1:0x0000]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x1049:1:0x0000]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x1049:1:0x0001]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x1049:1:0x0001]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x1049:1:0x0006]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x1049:1:0x0006]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x1049:1:0x0006]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x1049:1:0x0006]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xbd85](lumi.sensor_magnet.aq2): power source: Battery or Unknown
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xbd85](lumi.sensor_magnet.aq2): completed initialization
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x1049](lumi.sensor_magnet.aq2): power source: Battery or Unknown
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x1049](lumi.sensor_magnet.aq2): completed initialization
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xa42f](lumi.sensor_magnet.aq2): started initialization
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa42f:ZDO](lumi.sensor_magnet.aq2): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.sensor_magnet.aq2', ieee='00:15:8d:00:02:53:70:bc', last_seen=1579012668.572292)
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa42f:ZDO](lumi.sensor_magnet.aq2): channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x5e3c](lumi.sensor_magnet.aq2): started initialization
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x5e3c:ZDO](lumi.sensor_magnet.aq2): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.sensor_magnet.aq2', ieee='00:15:8d:00:02:75:32:10', last_seen=1579012401.3020155)
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x5e3c:ZDO](lumi.sensor_magnet.aq2): channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa42f:1:0x0000]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa42f:1:0x0000]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa42f:1:0x0001]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa42f:1:0x0001]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa42f:1:0x0006]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa42f:1:0x0006]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa42f:1:0x0006]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa42f:1:0x0006]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x5e3c:1:0x0000]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x5e3c:1:0x0000]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x5e3c:1:0x0001]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x5e3c:1:0x0001]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x5e3c:1:0x0006]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x5e3c:1:0x0006]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x5e3c:1:0x0006]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x5e3c:1:0x0006]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xa42f](lumi.sensor_magnet.aq2): power source: Battery or Unknown
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xa42f](lumi.sensor_magnet.aq2): completed initialization
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x5e3c](lumi.sensor_magnet.aq2): power source: Battery or Unknown
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x5e3c](lumi.sensor_magnet.aq2): completed initialization
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xb484](lumi.sensor_magnet): started initialization
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb484:ZDO](lumi.sensor_magnet): entry loaded from storage: ZhaDeviceEntry(name='LUMI lumi.sensor_magnet', ieee='00:15:8d:00:03:03:3d:99', last_seen=1579012280.2454953)
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb484:ZDO](lumi.sensor_magnet): channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xe726](lumi.sensor_ht): started initialization
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xe726:ZDO](lumi.sensor_ht): entry loaded from storage: ZhaDeviceEntry(name='None lumi.sensor_ht', ieee='00:15:8d:00:02:37:8a:ca', last_seen=1579012567.7198396)
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xe726:ZDO](lumi.sensor_ht): channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb484:1:0x0000]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb484:1:0x0000]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb484:1:0x0001]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb484:1:0x0001]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb484:1:0x0006]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb484:1:0x0006]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb484:1:0x0006]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb484:1:0x0006]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb484:1:0x0008]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb484:1:0x0008]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb484:1:0x0005]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb484:1:0x0005]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xe726:1:0x0000]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xe726:1:0x0000]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xe726:1:0x0001]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xe726:1:0x0001]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xe726:1:0x0402]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xe726:1:0x0402]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xe726:1:0x0405]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xe726:1:0x0405]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xe726:1:0x0005]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xe726:1:0x0005]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xe726:2:0x0005]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xe726:2:0x0005]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xe726:3:0x0005]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xe726:3:0x0005]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xb484](lumi.sensor_magnet): power source: Battery or Unknown
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xb484](lumi.sensor_magnet): completed initialization
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xe726](lumi.sensor_ht): power source: Battery or Unknown
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xe726](lumi.sensor_ht): completed initialization
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x4879](RH3040): started initialization
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4879:ZDO](RH3040): entry loaded from storage: ZhaDeviceEntry(name='TUYATEC-zn9wyqtr RH3040', ieee='ec:1b:bd:ff:fe:78:31:0a', last_seen=1579012464.3909516)
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4879:ZDO](RH3040): channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xf488](RH3040): started initialization
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xf488:ZDO](RH3040): entry loaded from storage: ZhaDeviceEntry(name='TUYATEC-zn9wyqtr RH3040', ieee='ec:1b:bd:ff:fe:78:3a:89', last_seen=1579012719.0127819)
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xf488:ZDO](RH3040): channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4879:1:0x0000]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4879:1:0x0000]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4879:1:0x0001]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4879:1:0x0001]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4879:1:0x0500]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x4879:1:0x0500]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xf488:1:0x0000]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xf488:1:0x0000]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xf488:1:0x0001]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xf488:1:0x0001]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xf488:1:0x0500]: initializing channel: from_cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xf488:1:0x0500]: channel: 'async_initialize' stage succeeded
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x4879](RH3040): power source: Battery or Unknown
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x4879](RH3040): completed initialization
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xf488](RH3040): power source: Battery or Unknown
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0xf488](RH3040): completed initialization
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xa42f:1:0x0006]: attempting to update onoff state - from cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xbd85:1:0x0006]: attempting to update onoff state - from cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x1049:1:0x0006]: attempting to update onoff state - from cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0x5e3c:1:0x0006]: attempting to update onoff state - from cache: True
2020-01-14 14:49:40 DEBUG (MainThread) [homeassistant.components.zha.core.channels] [0xb484:1:0x0006]: attempting to update onoff state - from cache: True
2020-01-14 14:49:47 ERROR (MainThread) [homeassistant.components.template.sensor] Could not render template Temperature (Morgan): UndefinedError: 'mappingproxy object' has no attribute 'Temperature'
2020-01-14 14:49:47 ERROR (MainThread) [homeassistant.components.template.sensor] Could not render template Temperature (Fraser): UndefinedError: 'mappingproxy object' has no attribute 'Temperature'
2020-01-14 14:49:47 ERROR (MainThread) [homeassistant.components.template.sensor] Could not render template Temperature (Living Room): UndefinedError: 'mappingproxy object' has no attribute 'Temperature'
2020-01-14 14:49:47 ERROR (MainThread) [homeassistant.components.template.sensor] Could not render template Temperature (Conservatory): UndefinedError: 'mappingproxy object' has no attribute 'Temperature'
2020-01-14 14:50:09 DEBUG (MainThread) [zigpy.device] [0x0000] Extending timeout for 0x03 request
2020-01-14 14:50:09 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 00:0d:6f:00:0b:5d:d1:25/0x0000
2020-01-14 14:50:09 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=0 clusterId=2 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=213>, 255, 0, 0x0000, 255, 255, b'\x03\x00\x00']
2020-01-14 14:50:09 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request 0x0002: [0x0000]
2020-01-14 14:50:09 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] Unsupported ZDO request:0x0002
2020-01-14 14:50:09 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=0 clusterId=32770 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=214>, 255, 0, 0x0000, 255, 255, b'\x03\x00\x00\x00\x00@\x8f\xcd\xabR\x80\x00\x00\x00\x80\x00\x00']
2020-01-14 14:50:09 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request 0x8002: [<Status.SUCCESS: 0>, 0x0000, <Optional byte1=0 byte2=64 mac_capability_flags=143 manufacturer_code=43981 maximum_buffer_size=82 maximum_incoming_transfer_size=128 server_mask=0 maximum_outgoing_transfer_size=128 descriptor_capability_field=0>]
2020-01-14 14:50:09 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] Unsupported ZDO request:0x8002
2020-01-14 14:50:09 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0, <EmberApsFrame profileId=0 clusterId=2 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=213>, 4, <EmberStatus.SUCCESS: 0>, b'']
2020-01-14 14:50:37 WARNING (MainThread) [zigpy.device] [0x0000] Requesting Node Descriptor failed: 
2020-01-14 14:50:37 INFO (MainThread) [zigpy.device] [0x0000] Discovering endpoints
2020-01-14 14:50:37 DEBUG (MainThread) [zigpy.device] [0x0000] Extending timeout for 0x05 request
2020-01-14 14:50:37 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 00:0d:6f:00:0b:5d:d1:25/0x0000
2020-01-14 14:50:37 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=0 clusterId=5 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=215>, 255, 0, 0x0000, 255, 255, b'\x05\x00\x00']
2020-01-14 14:50:37 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request 0x0005: [0x0000]
2020-01-14 14:50:37 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] Unsupported ZDO request:0x0005
2020-01-14 14:50:37 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=0 clusterId=32773 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=216>, 255, 0, 0x0000, 255, 255, b'\x05\x00\x00\x00\x01\x01']
2020-01-14 14:50:37 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request 0x8005: [<Status.SUCCESS: 0>, 0x0000, [1]]
2020-01-14 14:50:37 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] Unsupported ZDO request:0x8005
2020-01-14 14:50:37 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0, <EmberApsFrame profileId=0 clusterId=5 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=215>, 6, <EmberStatus.SUCCESS: 0>, b'']
2020-01-14 14:51:07 DEBUG (MainThread) [zigpy.device] [0x0000] Extending timeout for 0x07 request
2020-01-14 14:51:07 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 00:0d:6f:00:0b:5d:d1:25/0x0000
2020-01-14 14:51:07 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=0 clusterId=5 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=217>, 255, 0, 0x0000, 255, 255, b'\x07\x00\x00']
2020-01-14 14:51:07 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request 0x0005: [0x0000]
2020-01-14 14:51:07 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] Unsupported ZDO request:0x0005
2020-01-14 14:51:07 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=0 clusterId=32773 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=218>, 255, 0, 0x0000, 255, 255, b'\x07\x00\x00\x00\x01\x01']
2020-01-14 14:51:07 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request 0x8005: [<Status.SUCCESS: 0>, 0x0000, [1]]
2020-01-14 14:51:07 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] Unsupported ZDO request:0x8005
2020-01-14 14:51:07 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0, <EmberApsFrame profileId=0 clusterId=5 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=217>, 8, <EmberStatus.SUCCESS: 0>, b'']
2020-01-14 14:51:37 DEBUG (MainThread) [zigpy.device] [0x0000] Extending timeout for 0x09 request
2020-01-14 14:51:37 DEBUG (MainThread) [bellows.zigbee.application] Extending timeout for 00:0d:6f:00:0b:5d:d1:25/0x0000
2020-01-14 14:51:37 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=0 clusterId=5 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=219>, 255, 0, 0x0000, 255, 255, b'\t\x00\x00']
2020-01-14 14:51:37 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request 0x0005: [0x0000]
2020-01-14 14:51:37 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] Unsupported ZDO request:0x0005
2020-01-14 14:51:37 DEBUG (MainThread) [bellows.zigbee.application] Received incomingMessageHandler frame with [<EmberIncomingMessageType.INCOMING_UNICAST: 0>, <EmberApsFrame profileId=0 clusterId=32773 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=220>, 255, 0, 0x0000, 255, 255, b'\t\x00\x00\x00\x01\x01']
2020-01-14 14:51:37 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] ZDO request 0x8005: [<Status.SUCCESS: 0>, 0x0000, [1]]
2020-01-14 14:51:37 DEBUG (MainThread) [zigpy.zdo] [0x0000:zdo] Unsupported ZDO request:0x8005
2020-01-14 14:51:37 DEBUG (MainThread) [bellows.zigbee.application] Received messageSentHandler frame with [<EmberOutgoingMessageType.OUTGOING_DIRECT: 0>, 0, <EmberApsFrame profileId=0 clusterId=5 sourceEndpoint=0 destinationEndpoint=0 options=320 groupId=0 sequence=219>, 10, <EmberStatus.SUCCESS: 0>, b'']
2020-01-14 14:52:05 ERROR (MainThread) [zigpy.device] Failed ZDO request during device initialization: 
Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/zigpy/device.py", line 86, in _initialize
    epr = await self.zdo.Active_EP_req(self.nwk, tries=3, delay=2)
  File "/usr/local/lib/python3.7/site-packages/zigpy/util.py", line 88, in retry
    r = await func()
  File "/usr/local/lib/python3.7/site-packages/zigpy/device.py", line 191, in request
    result = await asyncio.wait_for(req.result, timeout)
  File "/usr/local/lib/python3.7/asyncio/tasks.py", line 449, in wait_for
    raise futures.TimeoutError()
concurrent.futures._base.TimeoutError

*Database (SELECT FROM "devices")**

00:0d:6f:00:12:35:22:91 0   2
00:15:8d:00:03:67:3f:64 48517   2
00:15:8d:00:02:75:33:5b 4169    2
00:15:8d:00:02:53:70:bc 42031   2
00:15:8d:00:02:75:32:10 24124   2
00:15:8d:00:03:03:3d:99 46212   2
00:15:8d:00:02:37:8a:ca 59174   2
ec:1b:bd:ff:fe:78:31:0a 18553   2
ec:1b:bd:ff:fe:78:3a:89 62600   2

*Database (SELECT FROM "endpoints")**

00:0d:6f:00:12:35:22:91 1   260 48879   1
00:15:8d:00:03:67:3f:64 1   260 24321   1
00:15:8d:00:02:75:33:5b 1   260 24321   1
00:15:8d:00:02:53:70:bc 1   260 24321   1
00:15:8d:00:02:75:32:10 1   260 24321   1
00:15:8d:00:03:03:3d:99 1   260 260 1
00:15:8d:00:02:37:8a:ca 1   260 24321   1
00:15:8d:00:02:37:8a:ca 2   260 24322   1
00:15:8d:00:02:37:8a:ca 3   260 24323   1
ec:1b:bd:ff:fe:78:31:0a 1   260 1026    1
ec:1b:bd:ff:fe:78:3a:89 1   260 1026    1
Adminiuga commented 4 years ago

Is this the second zigbee stick you are trying? Seems like the new one is 00:0d:6f:00:0b:5d:d1:25 and old one used to be 00:0d:6f:00:12:35:22:91 ?

If this is correct, try deleting all references to 00:0d:6f:00:12:35:22:91 from the zigbee.db

DELETE FROM attributes WHERE ieee='00:0d:6f:00:12:35:22:91';
DELETE FROM output_clusters WHERE ieee='00:0d:6f:00:12:35:22:91';
DELETE FROM clusters WHERE ieee='00:0d:6f:00:12:35:22:91';
DELETE FROM endpoints WHERE ieee='00:0d:6f:00:12:35:22:91';
DELETE FROM node_descriptors WHERE ieee='00:0d:6f:00:12:35:22:91';

and restart HA

shortbloke commented 4 years ago

Thanks @Adminiuga I previously had a different ZigBee adapter in my Pi3. This install on the Pi4 has only ever had the Nortek stick, but I did copy the config and files from the Pi3, so I guess the database had the old device though it wasn't showing anywhere and I don't see any mention of the "00:0d:6f:00:12:35:22:91" in the logs either.

Deleting the entry from all the database fields appears to have fixed it.