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
69.66k stars 28.82k forks source link

[ZHA] Irregular behavior with ZHA and STM32WB5 #111948

Closed Gunlek closed 1 day ago

Gunlek commented 4 months ago

The problem

I'm working on a general device development using STM32 and ZHA. I'm using a ConBee II, DeconZ and ZHA for the zigbee stack on home-assistant side and the full zigbee firmware stack on STM32 one.

Using the easiest STM32 blank code for zigbee, only activating logs on serial, I have irregular behavior on home-assistant side. By putting ZHA in pairing mode and rebooting STM32, the device join the network and sometimes HA handle this correctly, sometimes it starts interviewing the device, looping indefinitely, sometimes there is absolutely nothing on HA side even if STM32 successfully joined the network from its point of view.

I am sometimes successful in joining the network (up to interview handshake) in a repetitive way if I completly reboot HA between each try.

I didn't find any known issue between ZHA and STM32 but there is probably one here, wether it's a config one or a driver one.

Home Assistant is running on a Pi 3 with standard HA OS STM32WB5 is STM32WB5MM embedded on a STM32WB5MM-DK

Please find below the logs for a successful pairing from STM32 side and no pairing at all from HA side: STM32 Logs:

 [M0] [00000000.018][PLATFORM]        zb_startup_join_nwk_disc : Attempting network discovery. Scans = 3, Duration = 4
 [M0] [00000000.019][PLATFORM]                    nwk_scan_req : MLME-SCAN.request (wpan0): type=1, page=0, mask=0x07fff800, dur=4
 [M0] [00000001.082][PLATFORM]           nwk_handle_beacon_ind : BEACON addr16=0x0000, epid=0x129aa69b95b9eee3, ch=15, pan=0x08a5, depth= 0, lqi=175, cost=2, pjoin=1
 [M0] [00000004.238][PLATFORM]                    nwk_scan_req : MLME-SCAN.request (wpan0): type=1, page=0, mask=0x07fff800, dur=4
 [M0] [00000005.299][PLATFORM]           nwk_handle_beacon_ind : BEACON addr16=0x0000, epid=0x129aa69b95b9eee3, ch=15, pan=0x08a5, depth= 0, lqi=175, cost=2, pjoin=1
 [M0] [00000008.453][PLATFORM]                    nwk_scan_req : MLME-SCAN.request (wpan0): type=1, page=0, mask=0x07fff800, dur=4
 [M0] [00000009.521][PLATFORM]           nwk_handle_beacon_ind : BEACON addr16=0x0000, epid=0x129aa69b95b9eee3, ch=15, pan=0x08a5, depth= 0, lqi=171, cost=2, pjoin=1
 [M0] [00000000.017][PLATFORM]               nwk_join_try_next : Associating (src = 0x0080e125006f0c7e) to 0x0000 (epid = 0x129aa69b95b9eee3, lqi = 171, ch = 15)
 [M0] [00000000.592][PLATFORM]      ZbMonitorHandleTransKeyInd : Adding network key, sequence number = 0
 [M0] [00000000.593][PLATFORM]                ZbZdoDeviceAnnce : Sending Device_Annce for 0x11ba
[M4 APPLICATION] ZbStartup Callback (status = 0x00)
[M4 APPLICATION] Startup done !

ZHA Logs:

2024-03-01 13:38:55.331 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.write_parameter{'parameter_id': <NetworkParameter.permit_join: 33>, 'parameter': b'\xfe'} (seq=34)
2024-03-01 13:38:55.332 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0b22000900020021fe
2024-03-01 13:38:55.336 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0b22000800010021
2024-03-01 13:38:55.337 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.write_parameter{'status': <Status.SUCCESS: 0>, 'frame_length': 8, 'payload_length': 1, 'parameter_id': <NetworkParameter.permit_join: 33>} (seq 34)
2024-03-01 13:38:57.223 DEBUG (MainThread) [zigpy.application] Feeding watchdog
2024-03-01 13:38:57.225 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.write_parameter{'parameter_id': <NetworkParameter.watchdog_ttl: 38>, 'parameter': b'<\x00\x00\x00'} (seq=35)
2024-03-01 13:38:57.226 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0b23000c000500263c000000
2024-03-01 13:38:57.238 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0b23000800010026
2024-03-01 13:38:57.240 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.write_parameter{'status': <Status.SUCCESS: 0>, 'frame_length': 8, 'payload_length': 1, 'parameter_id': <NetworkParameter.watchdog_ttl: 38>} (seq 35)
2024-03-01 13:39:10.375 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 1, 12, 39, 10, 375459, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.Broadcast: 15>, address=<BroadcastAddress.ALL_ROUTERS_AND_COORDINATOR: 65532>), dst_ep=0, source_route=None, extended_timeout=False, tsn=22, profile_id=0, cluster_id=<ZDOCmd.Mgmt_Permit_Joining_req: 0x0036>, data=Serialized[b'\x16\xfe\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-03-01 13:39:10.378 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_request{'request_id': 23, 'flags': <DeconzSendDataFlags.NONE: 0>, 'dst': DeconzAddressEndpoint(address_mode=<AddressMode.NWK: 2>, address=0xFFFC, endpoint=0), 'profile_id': 0, 'cluster_id': <ZDOCmd.Mgmt_Permit_Joining_req: 0x0036>, 'src_ep': 0, 'asdu': b'\x16\xfe\x00', 'tx_options': <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 'radius': 0, 'relays': None} (seq=36)
2024-03-01 13:39:10.379 DEBUG (MainThread) [zigpy_deconz.uart] Send: 12240019001200170002fcff000000360000030016fe000200
2024-03-01 13:39:10.389 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x122400090002002217
2024-03-01 13:39:10.391 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_request{'status': <Status.SUCCESS: 0>, 'frame_length': 9, 'payload_length': 2, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'request_id': 23} (seq 36)
2024-03-01 13:39:11.029 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e25000700a600
2024-03-01 13:39:11.032 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': <Status.SUCCESS: 0>, 'frame_length': 7, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_CONFIRM|APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE|32: 41>), 'reserved': 0} (seq 37)
2024-03-01 13:39:11.034 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_confirm{} (seq=37)
2024-03-01 13:39:11.035 DEBUG (MainThread) [zigpy_deconz.uart] Send: 04250007000000
2024-03-01 13:39:11.039 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x04250013000c00221702fcff00000000000000
2024-03-01 13:39:11.043 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_confirm{'status': <Status.SUCCESS: 0>, 'frame_length': 19, 'payload_length': 12, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'request_id': 23, 'dst_addr': DeconzAddressEndpoint(address_mode=<AddressMode.NWK: 2>, address=0xFFFC, endpoint=0), 'src_ep': 0, 'confirm_status': <TXStatus.SUCCESS: 0>, 'reserved1': 0, 'reserved2': 0, 'reserved3': 0, 'reserved4': 0} (seq 37)
2024-03-01 13:39:11.045 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.write_parameter{'parameter_id': <NetworkParameter.permit_join: 33>, 'parameter': b'\xfe'} (seq=38)
2024-03-01 13:39:11.046 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0b26000900020021fe
2024-03-01 13:39:11.050 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0b26000800010021
2024-03-01 13:39:11.052 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.write_parameter{'status': <Status.SUCCESS: 0>, 'frame_length': 8, 'payload_length': 1, 'parameter_id': <NetworkParameter.permit_join: 33>} (seq 38)
2024-03-01 13:39:26.004 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c270012000b00037e0c6f0025e18000ffc8
2024-03-01 13:39:26.007 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 18, 'payload_length': 11, 'src_addr': DeconzAddress(address_mode=<AddressMode.IEEE: 3>, address=00:80:e1:25:00:6f:0c:7e), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 39)
2024-03-01 13:39:26.066 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c28000c00050002ba11ffc8
2024-03-01 13:39:26.069 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 40)
2024-03-01 13:39:26.131 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c29000c00050002ba11ffc8
2024-03-01 13:39:26.133 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 41)
2024-03-01 13:39:26.654 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c2a000c00050002ba11ffc9
2024-03-01 13:39:26.657 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -55, 'life_time': None, 'device_timeout': None} (seq 42)
2024-03-01 13:39:27.180 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c2b000c00050002ba11f8c8
2024-03-01 13:39:27.183 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 248, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 43)
2024-03-01 13:39:27.244 DEBUG (MainThread) [zigpy.application] Feeding watchdog
2024-03-01 13:39:27.246 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.write_parameter{'parameter_id': <NetworkParameter.watchdog_ttl: 38>, 'parameter': b'<\x00\x00\x00'} (seq=39)
2024-03-01 13:39:27.248 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0b27000c000500263c000000
2024-03-01 13:39:27.257 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0b27000800010026
2024-03-01 13:39:27.258 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.write_parameter{'status': <Status.SUCCESS: 0>, 'frame_length': 8, 'payload_length': 1, 'parameter_id': <NetworkParameter.watchdog_ttl: 38>} (seq 39)
2024-03-01 13:39:27.704 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c28000c00050002ba11ffc8
2024-03-01 13:39:27.707 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 40)
2024-03-01 13:39:31.373 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c29000c00050002ba11ffc8
2024-03-01 13:39:31.376 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 41)
2024-03-01 13:39:31.896 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c2a000c00050002ba11ffc8
2024-03-01 13:39:31.898 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 42)
2024-03-01 13:39:32.421 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c2b000c00050002ba11ffc8
2024-03-01 13:39:32.424 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 43)
2024-03-01 13:39:32.945 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c2c000c00050002ba11ffc8
2024-03-01 13:39:32.947 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 44)

I will add other logs for sucessful STM32 pairing, stuck on interview on HA side if I sucess in reproducing the issue one more time but this is honestly really irregular...

What version of Home Assistant Core has the issue?

core-2024.2.3

What was the last working version of Home Assistant Core?

No response

What type of installation are you running?

Home Assistant OS

Integration causing the issue

STM32

Link to integration documentation on our website

No response

Diagnostics information

{ "home_assistant": { "installation_type": "Home Assistant OS", "version": "2024.2.3", "dev": false, "hassio": true, "virtualenv": false, "python_version": "3.12.1", "docker": true, "arch": "aarch64", "timezone": "Europe/Paris", "os_name": "Linux", "os_version": "6.1.63-haos-raspi", "supervisor": "2024.02.1", "host_os": "Home Assistant OS 11.4", "docker_version": "24.0.7", "chassis": "embedded", "run_as_root": true }, "custom_components": {}, "integration_manifest": { "domain": "zha", "name": "Zigbee Home Automation", "after_dependencies": [ "onboarding", "usb" ], "codeowners": [ "@dmulcahey", "@adminiuga", "@puddly", "@TheJulianJES" ], "config_flow": true, "dependencies": [ "file_upload" ], "documentation": "https://www.home-assistant.io/integrations/zha", "iot_class": "local_polling", "loggers": [ "aiosqlite", "bellows", "crccheck", "pure_pcapy3", "zhaquirks", "zigpy", "zigpy_deconz", "zigpy_xbee", "zigpy_zigate", "zigpy_znp", "universal_silabs_flasher" ], "requirements": [ "bellows==0.38.0", "pyserial==3.5", "pyserial-asyncio==0.6", "zha-quirks==0.0.111", "zigpy-deconz==0.23.0", "zigpy==0.62.3", "zigpy-xbee==0.20.1", "zigpy-zigate==0.12.0", "zigpy-znp==0.12.1", "universal-silabs-flasher==0.0.18", "pyserial-asyncio-fast==0.11" ], "usb": [ { "vid": "10C4", "pid": "EA60", "description": "2652", "known_devices": [ "slae.sh cc2652rb stick" ] }, { "vid": "1A86", "pid": "55D4", "description": "sonoffplus", "known_devices": [ "sonoff zigbee dongle plus v2" ] }, { "vid": "10C4", "pid": "EA60", "description": "sonoffplus", "known_devices": [ "sonoff zigbee dongle plus" ] }, { "vid": "10C4", "pid": "EA60", "description": "tubeszb", "known_devices": [ "TubesZB Coordinator" ] }, { "vid": "1A86", "pid": "7523", "description": "tubeszb", "known_devices": [ "TubesZB Coordinator" ] }, { "vid": "1A86", "pid": "7523", "description": "zigstar", "known_devices": [ "ZigStar Coordinators" ] }, { "vid": "1CF1", "pid": "0030", "description": "conbee", "known_devices": [ "Conbee II" ] }, { "vid": "0403", "pid": "6015", "description": "conbee", "known_devices": [ "Conbee III" ] }, { "vid": "10C4", "pid": "8A2A", "description": "zigbee", "known_devices": [ "Nortek HUSBZB-1" ] }, { "vid": "0403", "pid": "6015", "description": "zigate", "known_devices": [ "ZiGate+" ] }, { "vid": "10C4", "pid": "EA60", "description": "zigate", "known_devices": [ "ZiGate" ] }, { "vid": "10C4", "pid": "8B34", "description": "bv 2010/10", "known_devices": [ "Bitron Video AV2010/10" ] } ], "zeroconf": [ { "type": "_esphomelib._tcp.local.", "name": "tube" }, { "type": "_zigate-zigbee-gateway._tcp.local.", "name": "zigate" }, { "type": "_zigstar_gw._tcp.local.", "name": "zigstar" }, { "type": "_uzg-01._tcp.local.", "name": "uzg-01" }, { "type": "_slzb-06._tcp.local.", "name": "slzb-06*" } ], "is_built_in": true }, "data": { "config": {}, "config_entry": { "entry_id": "29ab9cd8dd2284e321682eff3a48ad52", "version": 4, "minor_version": 1, "domain": "zha", "title": "ConBee II, s/n: DE2695397 - dresden elektronik ingenieurtechnik GmbH", "data": { "device": { "path": "/dev/serial/by-id/usb-dresden_elektronik_ingenieurtechnik_GmbH_ConBee_II_DE2695397-if00", "flow_control": null, "baudrate": 115200 }, "radio_type": "deconz" }, "options": {}, "pref_disable_new_entities": false, "pref_disable_polling": false, "source": "user", "unique_id": null, "disabled_by": null }, "application_state": { "node_info": { "nwk": 0, "ieee": "REDACTED", "logical_type": 0, "model": "Conbee II", "manufacturer": "dresden elektronik", "version": "0x26720700" }, "network_info": { "extended_pan_id": "REDACTED", "pan_id": 2213, "nwk_update_id": 1, "nwk_manager_id": 0, "channel": 15, "channel_mask": 32768, "security_level": 5, "network_key": "REDACTED", "tc_link_key": { "key": [ 90, 105, 103, 66, 101, 101, 65, 108, 108, 105, 97, 110, 99, 101, 48, 57 ], "tx_counter": 0, "rx_counter": 0, "seq": 0, "partner_ieee": "REDACTED" }, "key_table": [], "children": [], "nwk_addresses": {}, "stack_specific": {}, "metadata": { "deconz": { "version": "0x26720700" } }, "source": "zigpy-deconz@0.23.0" }, "counters": {}, "broadcast_counters": {}, "device_counters": {}, "group_counters": {} }, "energy_scan": { "11": 52.94117647058823, "12": 21.176470588235293, "13": 38.8235294117647, "14": 29.41176470588235, "15": 81.17647058823529, "16": 57.64705882352941, "17": 30.58823529411765, "18": 38.8235294117647, "19": 44.705882352941174, "20": 38.8235294117647, "21": 62.35294117647059, "22": 80.0, "23": 82.3529411764706, "24": 51.76470588235294, "25": 51.76470588235294, "26": 62.35294117647059 }, "versions": { "bellows": "0.38.0", "zigpy": "0.62.3", "zigpy_deconz": "0.23.0", "zigpy_xbee": "0.20.1", "zigpy_znp": "0.12.1", "zigpy_zigate": "0.12.0", "zhaquirks": "0.0.111" } } }

Example YAML snippet

No response

Anything in the logs that might be useful for us?

No response

Additional information

No response

home-assistant[bot] commented 4 months ago

Hey there @dmulcahey, @adminiuga, @puddly, @thejulianjes, mind taking a look at this issue as it has been labeled with an integration (zha) you are listed as a code owner for? Thanks!

Code owner commands Code owners of `zha` can trigger bot actions by commenting: - `@home-assistant close` Closes the issue. - `@home-assistant rename Awesome new title` Renames the issue. - `@home-assistant reopen` Reopen the issue. - `@home-assistant unassign zha` Removes the current integration label and assignees on the issue, add the integration domain after the command. - `@home-assistant add-label needs-more-information` Add a label (needs-more-information, problem in dependency, problem in custom component) to the issue. - `@home-assistant remove-label needs-more-information` Remove a label (needs-more-information, problem in dependency, problem in custom component) on the issue.

(message by CodeOwnersMention)


zha documentation zha source (message by IssueLinks)

puddly commented 4 months ago

According to your debug log, channel 15 is 85% congested. You should be getting a startup warning that tells you the same.

I suggest putting your Conbee 2 on a USB extension cable (if it isn't on one already) and moving it away from interference sources such as USB 3.0 ports, SSDs, 2.4GHz WiFi, and so on.

If you've done all that and you don't see any difference, change your ZigBee network's channel by going to the ZHA configuration page, clicking the pencil icon near the channel number, and leaving the dialog on "auto" so that ZHA will use the results of an energy scan to pick the best channel for you.

Gunlek commented 4 months ago

Thank you @puddly for your feedback I also tested on channel 20 and I have the same issue. Also, the stick is already on the tip of a USB extension cable. You're right, I should have selected the logs for a channel 20 try but the result is similar except this message

puddly commented 3 months ago

From your log, it looks like the device is able to join the network and then sends an announcement broadcast. None of this is present in the ZHA log you have. The Conbee would have sent serial messages indicating that a device has joined, especially if your device was sent the network key.

You also mention using deCONZ. ZHA communicates directly with the Conbee and expects exclusive control. If you have deCONZ running simultaneously, it will continuously interfere and break things. Remove deCONZ entirely, as it is unneeded.

Gunlek commented 3 months ago

I'm probably wrong saying that it uses deCONZ, I didn't installed any software manually, just used the default HA setup and ZHA has been automatically installed when I connected the Conbee USB key. I agree with you on the logs there is no message from the device joining the network...

puddly commented 3 months ago

Actually, I think your device is already associated:

[00000000.017][PLATFORM]               nwk_join_try_next : Associating (src = 0x0080e125006f0c7e) to 0x0000 (epid = 0x129aa69b95b9eee3, lqi = 171, ch = 15)
 [M0] 

The coordinator is receiving MAC poll messages from 0x11BA:

2024-03-01 13:39:26.007 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 18, 'payload_length': 11, 'src_addr': DeconzAddress(address_mode=<AddressMode.IEEE: 3>, address=00:80:e1:25:00:6f:0c:7e), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 39)
2024-03-01 13:39:27.707 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 40)
2024-03-01 13:39:31.376 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 41)
2024-03-01 13:39:31.898 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 42)
2024-03-01 13:39:32.424 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 43)
2024-03-01 13:39:32.947 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 44)

Can you upload a PCAP of the device joining and a few of the indefinite looping scenarios?

There are no known issues with the Conbee II working with any other production devices so I may have to lean towards there being issues on the dev kit side.

Gunlek commented 3 months ago

Setting up a PCAP on device side is - as far as I know - not possible due to the fact that STM32 is an embedded system's software...

Instead, I could execute a PCAP on raspberry's side to capture the packets exchanged with the Conbee, should it be relevant ?

Gunlek commented 3 months ago

Logs for successful pairing (and successful interview): Note that this successful pairing occured just after a fresh boot of the raspberry (no fresh install).

HA Side:

2024-03-03 20:15:05.527 DEBUG (MainThread) [zigpy.application] Feeding watchdog
2024-03-03 20:15:05.529 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.write_parameter{'parameter_id': <NetworkParameter.watchdog_ttl: 38>, 'parameter': b'<\x00\x00\x00'} (seq=58)
2024-03-03 20:15:05.530 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0b3a000c000500263c000000
2024-03-03 20:15:05.535 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0b3a000800010026
2024-03-03 20:15:05.537 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.write_parameter{'status': <Status.SUCCESS: 0>, 'frame_length': 8, 'payload_length': 1, 'parameter_id': <NetworkParameter.watchdog_ttl: 38>} (seq 58)
2024-03-03 20:15:09.849 ERROR (MainThread) [metno] Access to https://aa015h6buqvih86i1.api.met.no/weatherapi/locationforecast/2.0/complete returned error 'ClientConnectorError'
2024-03-03 20:15:19.395 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.write_parameter{'parameter_id': <NetworkParameter.permit_join: 33>, 'parameter': b'\xfe'} (seq=59)
2024-03-03 20:15:19.397 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0b3b000900020021fe
2024-03-03 20:15:19.401 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0b3b000800010021
2024-03-03 20:15:19.403 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.write_parameter{'status': <Status.SUCCESS: 0>, 'frame_length': 8, 'payload_length': 1, 'parameter_id': <NetworkParameter.permit_join: 33>} (seq 59)
2024-03-03 20:15:35.251 ERROR (MainThread) [metno] Access to https://aa015h6buqvih86i1.api.met.no/weatherapi/locationforecast/2.0/complete returned error 'ClientConnectorError'
2024-03-03 20:15:35.541 DEBUG (MainThread) [zigpy.application] Feeding watchdog
2024-03-03 20:15:35.543 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.write_parameter{'parameter_id': <NetworkParameter.watchdog_ttl: 38>, 'parameter': b'<\x00\x00\x00'} (seq=60)
2024-03-03 20:15:35.545 DEBUG (MainThread) [zigpy_deconz.uart] Send: 0b3c000c000500263c000000
2024-03-03 20:15:35.550 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0b3c000800010026
2024-03-03 20:15:35.552 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.write_parameter{'status': <Status.SUCCESS: 0>, 'frame_length': 8, 'payload_length': 1, 'parameter_id': <NetworkParameter.watchdog_ttl: 38>} (seq 60)
2024-03-03 20:15:38.494 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c3d0012000b00037e0c6f0025e18000ffba
2024-03-03 20:15:38.498 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 18, 'payload_length': 11, 'src_addr': DeconzAddress(address_mode=<AddressMode.IEEE: 3>, address=00:80:e1:25:00:6f:0c:7e), 'lqi': 255, 'rssi': -70, 'life_time': None, 'device_timeout': None} (seq 61)
2024-03-03 20:15:38.556 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c3e000c000500028f0fffba
2024-03-03 20:15:38.558 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'lqi': 255, 'rssi': -70, 'life_time': None, 'device_timeout': None} (seq 62)
2024-03-03 20:15:38.572 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e3f000700aa00
2024-03-03 20:15:38.573 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': <Status.SUCCESS: 0>, 'frame_length': 7, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_INDICATION|APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE|32: 42>), 'reserved': 0} (seq 63)
2024-03-03 20:15:38.578 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_indication{'flags': <DataIndicationFlags.Always_Use_NWK_Source_Addr: 1>} (seq=61)
2024-03-03 20:15:38.579 DEBUG (MainThread) [zigpy_deconz.uart] Send: 173d000800010001
2024-03-03 20:15:38.584 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x173d002a0023002202fdff00028f0f00000013000c00008f0f7e0c6f0025e180008400afff2c840400ba
2024-03-03 20:15:38.588 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_indication{'status': <Status.SUCCESS: 0>, 'frame_length': 42, 'payload_length': 35, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'dst_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0xFFFD), 'dst_ep': 0, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'src_ep': 0, 'profile_id': 0, 'cluster_id': 19, 'asdu': b'\x00\x8f\x0f~\x0co\x00%\xe1\x80\x00\x84', 'reserved1': 0, 'reserved2': 175, 'lqi': 255, 'reserved3': 44, 'reserved4': 132, 'reserved5': 4, 'reserved6': 0, 'rssi': -70} (seq 61)
2024-03-03 20:15:38.590 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 3, 19, 15, 38, 590105, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0F8F), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.Broadcast: 15>, address=<BroadcastAddress.RX_ON_WHEN_IDLE: 65533>), dst_ep=0, source_route=None, extended_timeout=False, tsn=None, profile_id=0, cluster_id=19, data=Serialized[b'\x00\x8f\x0f~\x0co\x00%\xe1\x80\x00\x84'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=255, rssi=-70)
2024-03-03 20:15:38.592 INFO (MainThread) [zigpy.application] New device 0x0f8f (00:80:e1:25:00:6f:0c:7e) joined the network
2024-03-03 20:15:38.593 DEBUG (MainThread) [zigpy.device] [0x0f8f] Scheduling initialization
2024-03-03 20:15:38.600 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x0F8F ieee=00:80:e1:25:00:6f:0c:7e is_initialized=False> from ep 0 to ep 0, cluster 19: Serialized[b'\x00\x8f\x0f~\x0co\x00%\xe1\x80\x00\x84']
2024-03-03 20:15:38.602 DEBUG (MainThread) [zigpy.zdo] [0x0f8f:zdo] ZDO request ZDOCmd.Device_annce: [0x0F8F, 00:80:e1:25:00:6f:0c:7e, 132]
2024-03-03 20:15:38.604 DEBUG (MainThread) [zigpy.util] Tries remaining: 5
2024-03-03 20:15:38.604 INFO (MainThread) [zigpy.device] [0x0f8f] Requesting 'Node Descriptor'
2024-03-03 20:15:38.605 DEBUG (MainThread) [zigpy.device] [0x0f8f] Extending timeout for 0x01 request
2024-03-03 20:15:38.606 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 3, 19, 15, 38, 606257, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0F8F), dst_ep=0, source_route=None, extended_timeout=True, tsn=1, profile_id=0, cluster_id=<ZDOCmd.Node_Desc_req: 0x0002>, data=Serialized[b'\x01\x8f\x0f'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-03-03 20:15:38.608 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7fa5b2d7b0>, 'UPDATE devices_v12 SET nwk=? WHERE ieee=?', (0x0F8F, 00:80:e1:25:00:6f:0c:7e))
2024-03-03 20:15:38.609 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_request{'request_id': 4, 'flags': <DeconzSendDataFlags.NONE: 0>, 'dst': DeconzAddressEndpoint(address_mode=<AddressMode.NWK: 2>, address=0x0F8F, endpoint=0), 'profile_id': 0, 'cluster_id': <ZDOCmd.Node_Desc_req: 0x0002>, 'src_ep': 0, 'asdu': b'\x01\x8f\x0f', 'tx_options': <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 'radius': 0, 'relays': None} (seq=62)
2024-03-03 20:15:38.611 DEBUG (MainThread) [zigpy_deconz.uart] Send: 123e00190012000400028f0f0000000200000300018f0f0200
2024-03-03 20:15:38.614 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7fa5b2d7b0>, 'UPDATE devices_v12 SET nwk=? WHERE ieee=?', (0x0F8F, 00:80:e1:25:00:6f:0c:7e)) completed
2024-03-03 20:15:38.620 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7fa5b2d7b0>)
2024-03-03 20:15:38.622 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x123e00090002002204
2024-03-03 20:15:38.623 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_request{'status': <Status.SUCCESS: 0>, 'frame_length': 9, 'payload_length': 2, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'request_id': 4} (seq 62)
2024-03-03 20:15:38.624 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c3f000c000500028f0fffba
2024-03-03 20:15:38.626 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'lqi': 255, 'rssi': -70, 'life_time': None, 'device_timeout': None} (seq 63)
2024-03-03 20:15:38.627 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7fa5b2d7b0>) completed
2024-03-03 20:15:39.149 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c40000c000500028f0fffba
2024-03-03 20:15:39.152 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'lqi': 255, 'rssi': -70, 'life_time': None, 'device_timeout': None} (seq 64)
2024-03-03 20:15:39.673 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e41000700a600
2024-03-03 20:15:39.676 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': <Status.SUCCESS: 0>, 'frame_length': 7, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_CONFIRM|APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE|32: 41>), 'reserved': 0} (seq 65)
2024-03-03 20:15:39.680 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c42000c000500028f0fffba
2024-03-03 20:15:39.683 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'lqi': 255, 'rssi': -70, 'life_time': None, 'device_timeout': None} (seq 66)
2024-03-03 20:15:39.685 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_confirm{} (seq=63)
2024-03-03 20:15:39.686 DEBUG (MainThread) [zigpy_deconz.uart] Send: 043f0007000000
2024-03-03 20:15:39.690 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x043f0013000c002204028f0f00000000000000
2024-03-03 20:15:39.692 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_confirm{'status': <Status.SUCCESS: 0>, 'frame_length': 19, 'payload_length': 12, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'request_id': 4, 'dst_addr': DeconzAddressEndpoint(address_mode=<AddressMode.NWK: 2>, address=0x0F8F, endpoint=0), 'src_ep': 0, 'confirm_status': <TXStatus.SUCCESS: 0>, 'reserved1': 0, 'reserved2': 0, 'reserved3': 0, 'reserved4': 0} (seq 63)
2024-03-03 20:15:39.735 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e40000700aa00
2024-03-03 20:15:39.737 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': <Status.SUCCESS: 0>, 'frame_length': 7, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_INDICATION|APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE|32: 42>), 'reserved': 0} (seq 64)
2024-03-03 20:15:39.739 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c41000c000500028f0fffba
2024-03-03 20:15:39.742 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'lqi': 255, 'rssi': -70, 'life_time': None, 'device_timeout': None} (seq 65)
2024-03-03 20:15:39.745 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_indication{'flags': <DataIndicationFlags.Always_Use_NWK_Source_Addr: 1>} (seq=64)
2024-03-03 20:15:39.746 DEBUG (MainThread) [zigpy_deconz.uart] Send: 1740000800010001
2024-03-03 20:15:39.748 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1740002f0028002202000000028f0f0000000280110001008f0f1a4084d71039d007002c80000300afff31840400ba
2024-03-03 20:15:39.751 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_indication{'status': <Status.SUCCESS: 0>, 'frame_length': 47, 'payload_length': 40, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'dst_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0000), 'dst_ep': 0, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'src_ep': 0, 'profile_id': 0, 'cluster_id': 32770, 'asdu': b'\x01\x00\x8f\x0f\x1a@\x84\xd7\x109\xd0\x07\x00,\x80\x00\x03', 'reserved1': 0, 'reserved2': 175, 'lqi': 255, 'reserved3': 49, 'reserved4': 132, 'reserved5': 4, 'reserved6': 0, 'rssi': -70} (seq 64)
2024-03-03 20:15:39.753 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 3, 19, 15, 39, 753214, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0F8F), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=None, profile_id=0, cluster_id=32770, data=Serialized[b'\x01\x00\x8f\x0f\x1a@\x84\xd7\x109\xd0\x07\x00,\x80\x00\x03'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=255, rssi=-70)
2024-03-03 20:15:39.756 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x0F8F ieee=00:80:e1:25:00:6f:0c:7e is_initialized=False> from ep 0 to ep 0, cluster 32770: Serialized[b'\x01\x00\x8f\x0f\x1a@\x84\xd7\x109\xd0\x07\x00,\x80\x00\x03']
2024-03-03 20:15:39.760 INFO (MainThread) [zigpy.device] [0x0f8f] Got Node Descriptor: NodeDescriptor(logical_type=<LogicalType.EndDevice: 2>, complex_descriptor_available=1, user_descriptor_available=1, reserved=0, aps_flags=0, frequency_band=<FrequencyBand.Freq2400MHz: 8>, mac_capability_flags=<MACCapabilityFlags.MainsPowered|AllocateAddress: 132>, manufacturer_code=4311, maximum_buffer_size=57, maximum_incoming_transfer_size=2000, server_mask=11264, maximum_outgoing_transfer_size=128, descriptor_capability_field=<DescriptorCapability.ExtendedActiveEndpointListAvailable|ExtendedSimpleDescriptorListAvailable: 3>, *allocate_address=True, *is_alternate_pan_coordinator=False, *is_coordinator=False, *is_end_device=True, *is_full_function_device=False, *is_mains_powered=True, *is_receiver_on_when_idle=False, *is_router=False, *is_security_capable=False)
2024-03-03 20:15:39.762 INFO (MainThread) [zigpy.device] [0x0f8f] Discovering endpoints
2024-03-03 20:15:39.763 DEBUG (MainThread) [zigpy.device] [0x0f8f] Extending timeout for 0x02 request
2024-03-03 20:15:39.764 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 3, 19, 15, 39, 763938, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0F8F), dst_ep=0, source_route=None, extended_timeout=True, tsn=2, profile_id=0, cluster_id=<ZDOCmd.Active_EP_req: 0x0005>, data=Serialized[b'\x02\x8f\x0f'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-03-03 20:15:39.766 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_request{'request_id': 5, 'flags': <DeconzSendDataFlags.NONE: 0>, 'dst': DeconzAddressEndpoint(address_mode=<AddressMode.NWK: 2>, address=0x0F8F, endpoint=0), 'profile_id': 0, 'cluster_id': <ZDOCmd.Active_EP_req: 0x0005>, 'src_ep': 0, 'asdu': b'\x02\x8f\x0f', 'tx_options': <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 'radius': 0, 'relays': None} (seq=65)
2024-03-03 20:15:39.767 DEBUG (MainThread) [zigpy_deconz.uart] Send: 124100190012000500028f0f0000000500000300028f0f0200
2024-03-03 20:15:39.773 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x124100090002002205
2024-03-03 20:15:39.775 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_request{'status': <Status.SUCCESS: 0>, 'frame_length': 9, 'payload_length': 2, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'request_id': 5} (seq 65)
2024-03-03 20:15:39.798 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e42000700a600
2024-03-03 20:15:39.800 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': <Status.SUCCESS: 0>, 'frame_length': 7, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_CONFIRM|APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE|32: 41>), 'reserved': 0} (seq 66)
2024-03-03 20:15:39.801 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c43000c000500028f0fffba
2024-03-03 20:15:39.802 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'lqi': 255, 'rssi': -70, 'life_time': None, 'device_timeout': None} (seq 67)
2024-03-03 20:15:39.805 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_confirm{} (seq=66)
2024-03-03 20:15:39.806 DEBUG (MainThread) [zigpy_deconz.uart] Send: 04420007000000
2024-03-03 20:15:39.810 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x04420013000c002205028f0f00000000000000
2024-03-03 20:15:39.812 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_confirm{'status': <Status.SUCCESS: 0>, 'frame_length': 19, 'payload_length': 12, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'request_id': 5, 'dst_addr': DeconzAddressEndpoint(address_mode=<AddressMode.NWK: 2>, address=0x0F8F, endpoint=0), 'src_ep': 0, 'confirm_status': <TXStatus.SUCCESS: 0>, 'reserved1': 0, 'reserved2': 0, 'reserved3': 0, 'reserved4': 0} (seq 66)
2024-03-03 20:15:39.859 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e43000700aa00
2024-03-03 20:15:39.862 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': <Status.SUCCESS: 0>, 'frame_length': 7, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_INDICATION|APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE|32: 42>), 'reserved': 0} (seq 67)
2024-03-03 20:15:39.864 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c44000c000500028f0fffba
2024-03-03 20:15:39.868 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'lqi': 255, 'rssi': -70, 'life_time': None, 'device_timeout': None} (seq 68)
2024-03-03 20:15:39.872 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_indication{'flags': <DataIndicationFlags.Always_Use_NWK_Source_Addr: 1>} (seq=67)
2024-03-03 20:15:39.873 DEBUG (MainThread) [zigpy_deconz.uart] Send: 1743000800010001
2024-03-03 20:15:39.875 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x17430025001e002202000000028f0f0000000580070002008f0f0201f200afff31840400ba
2024-03-03 20:15:39.878 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_indication{'status': <Status.SUCCESS: 0>, 'frame_length': 37, 'payload_length': 30, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'dst_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0000), 'dst_ep': 0, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'src_ep': 0, 'profile_id': 0, 'cluster_id': 32773, 'asdu': b'\x02\x00\x8f\x0f\x02\x01\xf2', 'reserved1': 0, 'reserved2': 175, 'lqi': 255, 'reserved3': 49, 'reserved4': 132, 'reserved5': 4, 'reserved6': 0, 'rssi': -70} (seq 67)
2024-03-03 20:15:39.880 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 3, 19, 15, 39, 880722, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0F8F), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=None, profile_id=0, cluster_id=32773, data=Serialized[b'\x02\x00\x8f\x0f\x02\x01\xf2'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=255, rssi=-70)
2024-03-03 20:15:39.882 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x0F8F ieee=00:80:e1:25:00:6f:0c:7e is_initialized=False> from ep 0 to ep 0, cluster 32773: Serialized[b'\x02\x00\x8f\x0f\x02\x01\xf2']
2024-03-03 20:15:39.884 INFO (MainThread) [zigpy.device] [0x0f8f] Discovered endpoints: [1, 242]
2024-03-03 20:15:39.884 INFO (MainThread) [zigpy.device] [0x0f8f] Initializing endpoints [<Endpoint id=1 in=[] out=[] status=<Status.NEW: 0>>, <Endpoint id=242 in=[] out=[] status=<Status.NEW: 0>>]
2024-03-03 20:15:39.885 INFO (MainThread) [zigpy.endpoint] [0x0f8f:1] Discovering endpoint information
2024-03-03 20:15:39.886 DEBUG (MainThread) [zigpy.device] [0x0f8f] Extending timeout for 0x03 request
2024-03-03 20:15:39.887 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 3, 19, 15, 39, 886968, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0F8F), dst_ep=0, source_route=None, extended_timeout=True, tsn=3, profile_id=0, cluster_id=<ZDOCmd.Simple_Desc_req: 0x0004>, data=Serialized[b'\x03\x8f\x0f\x01'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-03-03 20:15:39.890 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_request{'request_id': 6, 'flags': <DeconzSendDataFlags.NONE: 0>, 'dst': DeconzAddressEndpoint(address_mode=<AddressMode.NWK: 2>, address=0x0F8F, endpoint=0), 'profile_id': 0, 'cluster_id': <ZDOCmd.Simple_Desc_req: 0x0004>, 'src_ep': 0, 'asdu': b'\x03\x8f\x0f\x01', 'tx_options': <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 'radius': 0, 'relays': None} (seq=68)
2024-03-03 20:15:39.892 DEBUG (MainThread) [zigpy_deconz.uart] Send: 1244001a0013000600028f0f0000000400000400038f0f010200
2024-03-03 20:15:39.905 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x124400090002002206
2024-03-03 20:15:39.907 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_request{'status': <Status.SUCCESS: 0>, 'frame_length': 9, 'payload_length': 2, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'request_id': 6} (seq 68)
2024-03-03 20:15:39.918 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c45000c000500028f0fffba
2024-03-03 20:15:39.920 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'lqi': 255, 'rssi': -70, 'life_time': None, 'device_timeout': None} (seq 69)
2024-03-03 20:15:39.933 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e46000700a600
2024-03-03 20:15:39.935 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': <Status.SUCCESS: 0>, 'frame_length': 7, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_CONFIRM|APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE|32: 41>), 'reserved': 0} (seq 70)
2024-03-03 20:15:39.937 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_confirm{} (seq=69)
2024-03-03 20:15:39.938 DEBUG (MainThread) [zigpy_deconz.uart] Send: 04450007000000
2024-03-03 20:15:39.945 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x04450013000c002206028f0f00000000000000
2024-03-03 20:15:39.947 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_confirm{'status': <Status.SUCCESS: 0>, 'frame_length': 19, 'payload_length': 12, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'request_id': 6, 'dst_addr': DeconzAddressEndpoint(address_mode=<AddressMode.NWK: 2>, address=0x0F8F, endpoint=0), 'src_ep': 0, 'confirm_status': <TXStatus.SUCCESS: 0>, 'reserved1': 0, 'reserved2': 0, 'reserved3': 0, 'reserved4': 0} (seq 69)
2024-03-03 20:15:39.995 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e46000700aa00
2024-03-03 20:15:39.997 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': <Status.SUCCESS: 0>, 'frame_length': 7, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_INDICATION|APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE|32: 42>), 'reserved': 0} (seq 70)
2024-03-03 20:15:39.999 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c47000c000500028f0fffba
2024-03-03 20:15:40.002 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'lqi': 255, 'rssi': -70, 'life_time': None, 'device_timeout': None} (seq 71)
2024-03-03 20:15:40.005 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_indication{'flags': <DataIndicationFlags.Always_Use_NWK_Source_Addr: 1>} (seq=70)
2024-03-03 20:15:40.006 DEBUG (MainThread) [zigpy_deconz.uart] Send: 1746000800010001
2024-03-03 20:15:40.010 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1746002d0026002202000000028f0f00000004800f0003008f0f0a0104010000000100000000afff31840400ba
2024-03-03 20:15:40.013 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_indication{'status': <Status.SUCCESS: 0>, 'frame_length': 45, 'payload_length': 38, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'dst_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0000), 'dst_ep': 0, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'src_ep': 0, 'profile_id': 0, 'cluster_id': 32772, 'asdu': b'\x03\x00\x8f\x0f\n\x01\x04\x01\x00\x00\x00\x01\x00\x00\x00', 'reserved1': 0, 'reserved2': 175, 'lqi': 255, 'reserved3': 49, 'reserved4': 132, 'reserved5': 4, 'reserved6': 0, 'rssi': -70} (seq 70)
2024-03-03 20:15:40.014 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 3, 19, 15, 40, 14878, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0F8F), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=None, profile_id=0, cluster_id=32772, data=Serialized[b'\x03\x00\x8f\x0f\n\x01\x04\x01\x00\x00\x00\x01\x00\x00\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=255, rssi=-70)
2024-03-03 20:15:40.017 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x0F8F ieee=00:80:e1:25:00:6f:0c:7e is_initialized=False> from ep 0 to ep 0, cluster 32772: Serialized[b'\x03\x00\x8f\x0f\n\x01\x04\x01\x00\x00\x00\x01\x00\x00\x00']
2024-03-03 20:15:40.019 INFO (MainThread) [zigpy.endpoint] [0x0f8f:1] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=1, profile=260, device_type=0, device_version=0, input_clusters=[0], output_clusters=[])
2024-03-03 20:15:40.021 INFO (MainThread) [zigpy.endpoint] [0x0f8f:242] Discovering endpoint information
2024-03-03 20:15:40.022 DEBUG (MainThread) [zigpy.device] [0x0f8f] Extending timeout for 0x04 request
2024-03-03 20:15:40.023 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 3, 19, 15, 40, 23397, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0F8F), dst_ep=0, source_route=None, extended_timeout=True, tsn=4, profile_id=0, cluster_id=<ZDOCmd.Simple_Desc_req: 0x0004>, data=Serialized[b'\x04\x8f\x0f\xf2'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-03-03 20:15:40.025 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_request{'request_id': 7, 'flags': <DeconzSendDataFlags.NONE: 0>, 'dst': DeconzAddressEndpoint(address_mode=<AddressMode.NWK: 2>, address=0x0F8F, endpoint=0), 'profile_id': 0, 'cluster_id': <ZDOCmd.Simple_Desc_req: 0x0004>, 'src_ep': 0, 'asdu': b'\x04\x8f\x0f\xf2', 'tx_options': <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 'radius': 0, 'relays': None} (seq=71)
2024-03-03 20:15:40.026 DEBUG (MainThread) [zigpy_deconz.uart] Send: 1247001a0013000700028f0f0000000400000400048f0ff20200
2024-03-03 20:15:40.035 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x124700090002002207
2024-03-03 20:15:40.037 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_request{'status': <Status.SUCCESS: 0>, 'frame_length': 9, 'payload_length': 2, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'request_id': 7} (seq 71)
2024-03-03 20:15:40.060 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e48000700a600
2024-03-03 20:15:40.062 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': <Status.SUCCESS: 0>, 'frame_length': 7, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_CONFIRM|APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE|32: 41>), 'reserved': 0} (seq 72)
2024-03-03 20:15:40.063 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c49000c000500028f0fffba
2024-03-03 20:15:40.064 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'lqi': 255, 'rssi': -70, 'life_time': None, 'device_timeout': None} (seq 73)
2024-03-03 20:15:40.066 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_confirm{} (seq=72)
2024-03-03 20:15:40.066 DEBUG (MainThread) [zigpy_deconz.uart] Send: 04480007000000
2024-03-03 20:15:40.071 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x04480013000c002207028f0f00000000000000
2024-03-03 20:15:40.073 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_confirm{'status': <Status.SUCCESS: 0>, 'frame_length': 19, 'payload_length': 12, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'request_id': 7, 'dst_addr': DeconzAddressEndpoint(address_mode=<AddressMode.NWK: 2>, address=0x0F8F, endpoint=0), 'src_ep': 0, 'confirm_status': <TXStatus.SUCCESS: 0>, 'reserved1': 0, 'reserved2': 0, 'reserved3': 0, 'reserved4': 0} (seq 72)
2024-03-03 20:15:40.119 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e49000700aa00
2024-03-03 20:15:40.122 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': <Status.SUCCESS: 0>, 'frame_length': 7, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_INDICATION|APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE|32: 42>), 'reserved': 0} (seq 73)
2024-03-03 20:15:40.123 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c4a000c000500028f0fffba
2024-03-03 20:15:40.127 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'lqi': 255, 'rssi': -70, 'life_time': None, 'device_timeout': None} (seq 74)
2024-03-03 20:15:40.130 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_indication{'flags': <DataIndicationFlags.Always_Use_NWK_Source_Addr: 1>} (seq=73)
2024-03-03 20:15:40.131 DEBUG (MainThread) [zigpy_deconz.uart] Send: 1749000800010001
2024-03-03 20:15:40.135 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1749002d0026002202000000028f0f00000004800f0004008f0f0af2e0a16100000001210000afff31840400ba
2024-03-03 20:15:40.138 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_indication{'status': <Status.SUCCESS: 0>, 'frame_length': 45, 'payload_length': 38, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'dst_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0000), 'dst_ep': 0, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'src_ep': 0, 'profile_id': 0, 'cluster_id': 32772, 'asdu': b'\x04\x00\x8f\x0f\n\xf2\xe0\xa1a\x00\x00\x00\x01!\x00', 'reserved1': 0, 'reserved2': 175, 'lqi': 255, 'reserved3': 49, 'reserved4': 132, 'reserved5': 4, 'reserved6': 0, 'rssi': -70} (seq 73)
2024-03-03 20:15:40.140 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 3, 19, 15, 40, 140710, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0F8F), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=0, source_route=None, extended_timeout=False, tsn=None, profile_id=0, cluster_id=32772, data=Serialized[b'\x04\x00\x8f\x0f\n\xf2\xe0\xa1a\x00\x00\x00\x01!\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=255, rssi=-70)
2024-03-03 20:15:40.143 DEBUG (MainThread) [zigpy.application] Received frame on uninitialized device <Device model=None manuf=None nwk=0x0F8F ieee=00:80:e1:25:00:6f:0c:7e is_initialized=False> from ep 0 to ep 0, cluster 32772: Serialized[b'\x04\x00\x8f\x0f\n\xf2\xe0\xa1a\x00\x00\x00\x01!\x00']
2024-03-03 20:15:40.145 INFO (MainThread) [zigpy.endpoint] [0x0f8f:242] Discovered endpoint information: SizePrefixedSimpleDescriptor(endpoint=242, profile=41440, device_type=97, device_version=0, input_clusters=[], output_clusters=[33])
2024-03-03 20:15:40.148 DEBUG (MainThread) [zigpy.zcl] [0x0F8F:1:0x0000] Sending request header: ZCLHeader(frame_control=FrameControl<0x00>(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=False, direction=<Direction.Client_to_Server: 0>, disable_default_response=0, reserved=0, *is_cluster=False, *is_general=True), tsn=5, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Client_to_Server: 0>)
2024-03-03 20:15:40.152 DEBUG (MainThread) [zigpy.zcl] [0x0F8F:1:0x0000] Sending request: Read_Attributes(attribute_ids=[4, 5])
2024-03-03 20:15:40.153 DEBUG (MainThread) [zigpy.device] [0x0f8f] Extending timeout for 0x05 request
2024-03-03 20:15:40.154 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 3, 19, 15, 40, 154491, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0F8F), dst_ep=1, source_route=None, extended_timeout=True, tsn=5, profile_id=260, cluster_id=0, data=Serialized[b'\x00\x05\x00\x04\x00\x05\x00'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-03-03 20:15:40.157 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_request{'request_id': 8, 'flags': <DeconzSendDataFlags.NONE: 0>, 'dst': DeconzAddressEndpoint(address_mode=<AddressMode.NWK: 2>, address=0x0F8F, endpoint=1), 'profile_id': 260, 'cluster_id': 0, 'src_ep': 1, 'asdu': b'\x00\x05\x00\x04\x00\x05\x00', 'tx_options': <DeconzTransmitOptions.USE_NWK_KEY_SECURITY: 2>, 'radius': 0, 'relays': None} (seq=74)
2024-03-03 20:15:40.158 DEBUG (MainThread) [zigpy_deconz.uart] Send: 124a001d0016000800028f0f0104010000010700000500040005000200
2024-03-03 20:15:40.166 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x124a00090002002208
2024-03-03 20:15:40.167 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_request{'status': <Status.SUCCESS: 0>, 'frame_length': 9, 'payload_length': 2, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'request_id': 8} (seq 74)
2024-03-03 20:15:40.183 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e4b000700a600
2024-03-03 20:15:40.185 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': <Status.SUCCESS: 0>, 'frame_length': 7, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_CONFIRM|APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE|32: 41>), 'reserved': 0} (seq 75)
2024-03-03 20:15:40.186 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c4c000c000500028f0fffba
2024-03-03 20:15:40.187 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'lqi': 255, 'rssi': -70, 'life_time': None, 'device_timeout': None} (seq 76)
2024-03-03 20:15:40.190 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_confirm{} (seq=75)
2024-03-03 20:15:40.191 DEBUG (MainThread) [zigpy_deconz.uart] Send: 044b0007000000
2024-03-03 20:15:40.198 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x044b0013000c002208028f0f01010000000000
2024-03-03 20:15:40.201 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_confirm{'status': <Status.SUCCESS: 0>, 'frame_length': 19, 'payload_length': 12, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'request_id': 8, 'dst_addr': DeconzAddressEndpoint(address_mode=<AddressMode.NWK: 2>, address=0x0F8F, endpoint=1), 'src_ep': 1, 'confirm_status': <TXStatus.SUCCESS: 0>, 'reserved1': 0, 'reserved2': 0, 'reserved3': 0, 'reserved4': 0} (seq 75)
2024-03-03 20:15:40.246 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e4c000700aa00
2024-03-03 20:15:40.248 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.device_state_changed{'status': <Status.SUCCESS: 0>, 'frame_length': 7, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_INDICATION|APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE|32: 42>), 'reserved': 0} (seq 76)
2024-03-03 20:15:40.250 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c4d000c000500028f0fffba
2024-03-03 20:15:40.252 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'lqi': 255, 'rssi': -70, 'life_time': None, 'device_timeout': None} (seq 77)
2024-03-03 20:15:40.258 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_indication{'flags': <DataIndicationFlags.Always_Use_NWK_Source_Addr: 1>} (seq=76)
2024-03-03 20:15:40.259 DEBUG (MainThread) [zigpy_deconz.uart] Send: 174c000800010001
2024-03-03 20:15:40.263 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x174c0044003d002202000001028f0f01040100002600180501040000421253544d6963726f656c656374726f6e696373050000420753544d3332574200afff31840400ba
2024-03-03 20:15:40.265 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_indication{'status': <Status.SUCCESS: 0>, 'frame_length': 68, 'payload_length': 61, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 8>), 'dst_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0000), 'dst_ep': 1, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'src_ep': 1, 'profile_id': 260, 'cluster_id': 0, 'asdu': b'\x18\x05\x01\x04\x00\x00B\x12STMicroelectronics\x05\x00\x00B\x07STM32WB', 'reserved1': 0, 'reserved2': 175, 'lqi': 255, 'reserved3': 49, 'reserved4': 132, 'reserved5': 4, 'reserved6': 0, 'rssi': -70} (seq 76)
2024-03-03 20:15:40.267 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 3, 19, 15, 40, 267686, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0F8F), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), dst_ep=1, source_route=None, extended_timeout=False, tsn=None, profile_id=260, cluster_id=0, data=Serialized[b'\x18\x05\x01\x04\x00\x00B\x12STMicroelectronics\x05\x00\x00B\x07STM32WB'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=255, rssi=-70)
2024-03-03 20:15:40.270 DEBUG (MainThread) [zigpy.zcl] [0x0F8F:1:0x0000] Received ZCL frame: b'\x18\x05\x01\x04\x00\x00B\x12STMicroelectronics\x05\x00\x00B\x07STM32WB'
2024-03-03 20:15:40.272 DEBUG (MainThread) [zigpy.zcl] [0x0F8F:1:0x0000] Decoded ZCL frame header: ZCLHeader(frame_control=FrameControl<0x18>(frame_type=<FrameType.GLOBAL_COMMAND: 0>, is_manufacturer_specific=0, direction=<Direction.Server_to_Client: 1>, disable_default_response=1, reserved=0, *is_cluster=False, *is_general=True), tsn=5, command_id=1, *direction=<Direction.Server_to_Client: 1>)
2024-03-03 20:15:40.278 DEBUG (MainThread) [zigpy.zcl] [0x0F8F:1:0x0000] Decoded ZCL frame: Basic:Read_Attributes_rsp(status_records=[ReadAttributeRecord(attrid=0x0004, status=<Status.SUCCESS: 0>, value=TypeValue(type=CharacterString, value='STMicroelectronics')), ReadAttributeRecord(attrid=0x0005, status=<Status.SUCCESS: 0>, value=TypeValue(type=CharacterString, value='STM32WB'))])
2024-03-03 20:15:40.282 INFO (MainThread) [zigpy.device] [0x0f8f] Read model 'STM32WB' and manufacturer 'STMicroelectronics' from <Endpoint id=1 in=[basic:0x0000] out=[] status=<Status.ZDO_INIT: 1>>
2024-03-03 20:15:40.282 INFO (MainThread) [zigpy.device] [0x0f8f] Discovered basic device information for <Device model='STM32WB' manuf='STMicroelectronics' nwk=0x0F8F ieee=00:80:e1:25:00:6f:0c:7e is_initialized=True>
2024-03-03 20:15:40.283 DEBUG (MainThread) [zigpy.application] Device is initialized <Device model='STM32WB' manuf='STMicroelectronics' nwk=0x0F8F ieee=00:80:e1:25:00:6f:0c:7e is_initialized=True>
2024-03-03 20:15:40.290 DEBUG (MainThread) [zigpy.quirks.registry] Checking quirks for STMicroelectronics STM32WB (00:80:e1:25:00:6f:0c:7e)
2024-03-03 20:15:40.290 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xbee.xbee_io.XBeeSensor'>
2024-03-03 20:15:40.291 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {232, 230} {1, 242}
2024-03-03 20:15:40.291 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.xbee.xbee3_io.XBee3Sensor'>
2024-03-03 20:15:40.291 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {232, 230} {1, 242}
2024-03-03 20:15:40.292 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.tuya.ts0201.MoesTemperatureHumidtySensorWithScreen'>
2024-03-03 20:15:40.292 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242}
2024-03-03 20:15:40.293 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.smartthings.tag_v4.SmartThingsTagV4'>
2024-03-03 20:15:40.293 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242}
2024-03-03 20:15:40.294 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.smartthings.multi.SmartthingsMultiPurposeSensor'>
2024-03-03 20:15:40.294 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242}
2024-03-03 20:15:40.294 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.netvox.z308e3ed.Z308E3ED'>
2024-03-03 20:15:40.295 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {1} {1, 242}
2024-03-03 20:15:40.295 DEBUG (MainThread) [zigpy.quirks.registry] Considering <class 'zhaquirks.gledopto.soposhgu10.SoposhGU10'>
2024-03-03 20:15:40.295 DEBUG (MainThread) [zigpy.quirks.registry] Fail because endpoint list mismatch: {11, 13} {1, 242}
2024-03-03 20:15:40.301 DEBUG (MainThread) [homeassistant.components.zha.core.endpoint] Creating cluster handler for cluster id: 0 class: <class 'homeassistant.components.zha.core.cluster_handlers.general.BasicClusterHandler'>
2024-03-03 20:15:40.302 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] Discovering entities for endpoint: 00:80:e1:25:00:6f:0c:7e-1
2024-03-03 20:15:40.303 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7fa5b2d7b0>, '\n            INSERT INTO attributes_cache_v12\n            VALUES (:ieee, :endpoint_id, :cluster_id, :attrid, :value, :timestamp)\n                ON CONFLICT (ieee, endpoint_id, cluster, attrid) DO UPDATE\n                SET value=excluded.value, last_updated=excluded.last_updated\n                WHERE\n                    value != excluded.value\n                    OR :timestamp - last_updated > :min_update_delta\n            ', {'ieee': 00:80:e1:25:00:6f:0c:7e, 'endpoint_id': 1, 'cluster_id': 0, 'attrid': 4, 'value': 'STMicroelectronics', 'timestamp': 1709493340.281755, 'min_update_delta': 30.0})
2024-03-03 20:15:40.310 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'sensor' component -> 'RSSISensor' using ['basic']
2024-03-03 20:15:40.311 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] 'sensor' component -> 'LQISensor' using ['basic']
2024-03-03 20:15:40.315 DEBUG (Thread-5) [aiosqlite] returning exception FOREIGN KEY constraint failed
2024-03-03 20:15:40.323 DEBUG (MainThread) [homeassistant.components.zha.core.discovery] Discovering entities for endpoint: 00:80:e1:25:00:6f:0c:7e-242
2024-03-03 20:15:40.339 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0F8F](STM32WB): starting availability checks - interval: 65
2024-03-03 20:15:40.342 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] device - 0x0F8F:00:80:e1:25:00:6f:0c:7e entering async_device_initialized - is_new_join: True
2024-03-03 20:15:40.342 DEBUG (MainThread) [homeassistant.components.zha.core.gateway] device - 0x0F8F:00:80:e1:25:00:6f:0c:7e has joined the ZHA zigbee network
2024-03-03 20:15:40.344 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0F8F](STM32WB): started configuration
2024-03-03 20:15:40.349 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x0F8F:ZDO](STM32WB): 'async_configure' stage succeeded
2024-03-03 20:15:40.354 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c4d000c000500028f0fffba
2024-03-03 20:15:40.356 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'lqi': 255, 'rssi': -70, 'life_time': None, 'device_timeout': None} (seq 77)
2024-03-03 20:15:40.359 DEBUG (MainThread) [zigpy.appdb] Error handling '_save_attribute' event with (00:80:e1:25:00:6f:0c:7e, 1, 0, 4, 'STMicroelectronics', datetime.datetime(2024, 3, 3, 19, 15, 40, 281755, tzinfo=datetime.timezone.utc)) params: FOREIGN KEY constraint failed
2024-03-03 20:15:40.360 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x0F8F:1:0x0000]: Configuring cluster attribute reporting
2024-03-03 20:15:40.361 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x0F8F:1:0x0000]: finished cluster handler configuration
2024-03-03 20:15:40.362 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7fa5b2d7b0>, '\n            INSERT INTO attributes_cache_v12\n            VALUES (:ieee, :endpoint_id, :cluster_id, :attrid, :value, :timestamp)\n                ON CONFLICT (ieee, endpoint_id, cluster, attrid) DO UPDATE\n                SET value=excluded.value, last_updated=excluded.last_updated\n                WHERE\n                    value != excluded.value\n                    OR :timestamp - last_updated > :min_update_delta\n            ', {'ieee': 00:80:e1:25:00:6f:0c:7e, 'endpoint_id': 1, 'cluster_id': 0, 'attrid': 5, 'value': 'STM32WB', 'timestamp': 1709493340.281886, 'min_update_delta': 30.0})
2024-03-03 20:15:40.365 DEBUG (Thread-5) [aiosqlite] returning exception FOREIGN KEY constraint failed
2024-03-03 20:15:40.367 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x0F8F:1:0x0000]: 'async_configure' stage succeeded
2024-03-03 20:15:40.368 DEBUG (MainThread) [zigpy.appdb] Error handling '_save_attribute' event with (00:80:e1:25:00:6f:0c:7e, 1, 0, 5, 'STM32WB', datetime.datetime(2024, 3, 3, 19, 15, 40, 281886, tzinfo=datetime.timezone.utc)) params: FOREIGN KEY constraint failed
2024-03-03 20:15:40.369 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0F8F](STM32WB): completed configuration
2024-03-03 20:15:40.370 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0F8F](STM32WB): started initialization
2024-03-03 20:15:40.370 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x0F8F:ZDO](STM32WB): 'async_initialize' stage succeeded
2024-03-03 20:15:40.372 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x0F8F:1:0x0000]: initializing cluster handler: from_cache: False
2024-03-03 20:15:40.373 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x0F8F:1:0x0000]: finished cluster handler initialization
2024-03-03 20:15:40.374 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO devices_v12 (ieee, nwk, status, last_seen)\n                    VALUES (?, ?, ?, ?)\n                    ON CONFLICT (ieee)\n                    DO UPDATE SET\n                        nwk=excluded.nwk,\n                        status=excluded.status,\n                        last_seen=excluded.last_seen', (00:80:e1:25:00:6f:0c:7e, 0x0F8F, <Status.ENDPOINTS_INIT: 2>, 1709493340.267686))
2024-03-03 20:15:40.376 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO devices_v12 (ieee, nwk, status, last_seen)\n                    VALUES (?, ?, ?, ?)\n                    ON CONFLICT (ieee)\n                    DO UPDATE SET\n                        nwk=excluded.nwk,\n                        status=excluded.status,\n                        last_seen=excluded.last_seen', (00:80:e1:25:00:6f:0c:7e, 0x0F8F, <Status.ENDPOINTS_INIT: 2>, 1709493340.267686)) completed
2024-03-03 20:15:40.378 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x0F8F:1:0x0000]: 'async_initialize' stage succeeded
2024-03-03 20:15:40.379 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0F8F](STM32WB): power source: Mains
2024-03-03 20:15:40.379 DEBUG (MainThread) [homeassistant.components.zha.core.device] [0x0F8F](STM32WB): completed initialization
2024-03-03 20:15:40.391 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method execute of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO node_descriptors_v12\n                VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee)\n                    DO UPDATE SET\n                logical_type=excluded.logical_type,\n                complex_descriptor_available=excluded.complex_descriptor_available,\n                user_descriptor_available=excluded.user_descriptor_available,\n                reserved=excluded.reserved,\n                aps_flags=excluded.aps_flags,\n                frequency_band=excluded.frequency_band,\n                mac_capability_flags=excluded.mac_capability_flags,\n                manufacturer_code=excluded.manufacturer_code,\n                maximum_buffer_size=excluded.maximum_buffer_size,\n                maximum_incoming_transfer_size=excluded.maximum_incoming_transfer_size,\n                server_mask=excluded.server_mask,\n                maximum_outgoing_transfer_size=excluded.maximum_outgoing_transfer_size,\n                descriptor_capability_field=excluded.descriptor_capability_field', (00:80:e1:25:00:6f:0c:7e, <LogicalType.EndDevice: 2>, 1, 1, 0, 0, <FrequencyBand.Freq2400MHz: 8>, <MACCapabilityFlags.MainsPowered|AllocateAddress: 132>, 4311, 57, 2000, 11264, 128, <DescriptorCapability.ExtendedActiveEndpointListAvailable|ExtendedSimpleDescriptorListAvailable: 3>))
2024-03-03 20:15:40.392 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method execute of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO node_descriptors_v12\n                VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee)\n                    DO UPDATE SET\n                logical_type=excluded.logical_type,\n                complex_descriptor_available=excluded.complex_descriptor_available,\n                user_descriptor_available=excluded.user_descriptor_available,\n                reserved=excluded.reserved,\n                aps_flags=excluded.aps_flags,\n                frequency_band=excluded.frequency_band,\n                mac_capability_flags=excluded.mac_capability_flags,\n                manufacturer_code=excluded.manufacturer_code,\n                maximum_buffer_size=excluded.maximum_buffer_size,\n                maximum_incoming_transfer_size=excluded.maximum_incoming_transfer_size,\n                server_mask=excluded.server_mask,\n                maximum_outgoing_transfer_size=excluded.maximum_outgoing_transfer_size,\n                descriptor_capability_field=excluded.descriptor_capability_field', (00:80:e1:25:00:6f:0c:7e, <LogicalType.EndDevice: 2>, 1, 1, 0, 0, <FrequencyBand.Freq2400MHz: 8>, <MACCapabilityFlags.MainsPowered|AllocateAddress: 132>, 4311, 57, 2000, 11264, 128, <DescriptorCapability.ExtendedActiveEndpointListAvailable|ExtendedSimpleDescriptorListAvailable: 3>)) completed
2024-03-03 20:15:40.412 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO endpoints_v12 VALUES (?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id)\n                    DO UPDATE SET\n                        profile_id=excluded.profile_id,\n                        device_type=excluded.device_type,\n                        status=excluded.status', [(00:80:e1:25:00:6f:0c:7e, 1, 260, <DeviceType.ON_OFF_SWITCH: 0>, <Status.ZDO_INIT: 1>), (00:80:e1:25:00:6f:0c:7e, 242, 41440, 97, <Status.ZDO_INIT: 1>)])
2024-03-03 20:15:40.419 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO endpoints_v12 VALUES (?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id)\n                    DO UPDATE SET\n                        profile_id=excluded.profile_id,\n                        device_type=excluded.device_type,\n                        status=excluded.status', [(00:80:e1:25:00:6f:0c:7e, 1, 260, <DeviceType.ON_OFF_SWITCH: 0>, <Status.ZDO_INIT: 1>), (00:80:e1:25:00:6f:0c:7e, 242, 41440, 97, <Status.ZDO_INIT: 1>)]) completed
2024-03-03 20:15:40.423 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO in_clusters_v12 VALUES (?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster)\n                    DO NOTHING', [(00:80:e1:25:00:6f:0c:7e, 1, 0)])
2024-03-03 20:15:40.426 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO in_clusters_v12 VALUES (?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster)\n                    DO NOTHING', [(00:80:e1:25:00:6f:0c:7e, 1, 0)]) completed
2024-03-03 20:15:40.430 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO attributes_cache_v12 VALUES (?, ?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster, attrid)\n                    DO UPDATE SET value=excluded.value, last_updated=excluded.last_updated', [(00:80:e1:25:00:6f:0c:7e, 1, 0, 4, 'STMicroelectronics', 1709493340.281755), (00:80:e1:25:00:6f:0c:7e, 1, 0, 5, 'STM32WB', 1709493340.281886)])
2024-03-03 20:15:40.437 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO attributes_cache_v12 VALUES (?, ?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster, attrid)\n                    DO UPDATE SET value=excluded.value, last_updated=excluded.last_updated', [(00:80:e1:25:00:6f:0c:7e, 1, 0, 4, 'STMicroelectronics', 1709493340.281755), (00:80:e1:25:00:6f:0c:7e, 1, 0, 5, 'STM32WB', 1709493340.281886)]) completed
2024-03-03 20:15:40.442 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO unsupported_attributes_v12 VALUES (?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster, attrid)\n                    DO NOTHING', [])
2024-03-03 20:15:40.443 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO unsupported_attributes_v12 VALUES (?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster, attrid)\n                    DO NOTHING', []) completed
2024-03-03 20:15:40.446 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO out_clusters_v12 VALUES (?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster)\n                    DO NOTHING', [])
2024-03-03 20:15:40.447 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO out_clusters_v12 VALUES (?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster)\n                    DO NOTHING', []) completed
2024-03-03 20:15:40.451 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO in_clusters_v12 VALUES (?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster)\n                    DO NOTHING', [])
2024-03-03 20:15:40.452 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO in_clusters_v12 VALUES (?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster)\n                    DO NOTHING', []) completed
2024-03-03 20:15:40.455 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO attributes_cache_v12 VALUES (?, ?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster, attrid)\n                    DO UPDATE SET value=excluded.value, last_updated=excluded.last_updated', [])
2024-03-03 20:15:40.456 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO attributes_cache_v12 VALUES (?, ?, ?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster, attrid)\n                    DO UPDATE SET value=excluded.value, last_updated=excluded.last_updated', []) completed
2024-03-03 20:15:40.459 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO unsupported_attributes_v12 VALUES (?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster, attrid)\n                    DO NOTHING', [])
2024-03-03 20:15:40.460 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO unsupported_attributes_v12 VALUES (?, ?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster, attrid)\n                    DO NOTHING', []) completed
2024-03-03 20:15:40.463 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO out_clusters_v12 VALUES (?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster)\n                    DO NOTHING', [(00:80:e1:25:00:6f:0c:7e, 242, 33)])
2024-03-03 20:15:40.464 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method executemany of sqlite3.Connection object at 0x7fa5b2d7b0>, 'INSERT INTO out_clusters_v12 VALUES (?, ?, ?)\n                    ON CONFLICT (ieee, endpoint_id, cluster)\n                    DO NOTHING', [(00:80:e1:25:00:6f:0c:7e, 242, 33)]) completed
2024-03-03 20:15:40.467 DEBUG (Thread-5) [aiosqlite] executing functools.partial(<built-in method commit of sqlite3.Connection object at 0x7fa5b2d7b0>)
2024-03-03 20:15:40.474 DEBUG (Thread-5) [aiosqlite] operation functools.partial(<built-in method commit of sqlite3.Connection object at 0x7fa5b2d7b0>) completed
2024-03-03 20:15:43.867 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1c4e000c000500028f0fffba
2024-03-03 20:15:43.869 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0F8F), 'lqi': 255, 'rssi': -70, 'life_time': None, 'device_timeout': None} (seq 78)

STM32 Side:

[M4 APPLICATION] APP_ZIGBEE_StackLayersInit
[M4 APPLICATION] Network config : APP_STARTUP_DISTRIBUTED
 [M0] [00000000.020][PLATFORM]                  ZbNlmeResetReq : NLME-RESET.request (warmStart = 0)
 [M0] [00000000.018][PLATFORM]        zb_startup_join_nwk_disc : Attempting network discovery. Scans = 3, Duration = 4
 [M0] [00000000.019][PLATFORM]                    nwk_scan_req : MLME-SCAN.request (wpan0): type=1, page=0, mask=0x07fff800, dur=4
 [M0] [00000001.024][PLATFORM]          zcl_persist_send_cache : Sending persist PUSH (ep = 242, cl = 0x0021, len = 6)
 [M0] [00000001.081][PLATFORM]           nwk_handle_beacon_ind : BEACON addr16=0x0000, epid=0x129aa69b95b9eee3, ch=15, pan=0x08a5, depth= 0, lqi=126, cost=3, pjoin=1
 [M0] [00000004.233][PLATFORM]                    nwk_scan_req : MLME-SCAN.request (wpan0): type=1, page=0, mask=0x07fff800, dur=4
 [M0] [00000005.298][PLATFORM]           nwk_handle_beacon_ind : BEACON addr16=0x0000, epid=0x129aa69b95b9eee3, ch=15, pan=0x08a5, depth= 0, lqi=126, cost=3, pjoin=1
 [M0] [00000008.450][PLATFORM]                    nwk_scan_req : MLME-SCAN.request (wpan0): type=1, page=0, mask=0x07fff800, dur=4
 [M0] [00000009.513][PLATFORM]           nwk_handle_beacon_ind : BEACON addr16=0x0000, epid=0x129aa69b95b9eee3, ch=15, pan=0x08a5, depth= 0, lqi=126, cost=3, pjoin=1
 [M0] [00000000.017][PLATFORM]               nwk_join_try_next : Associating (src = 0x0080e125006f0c7e) to 0x0000 (epid = 0x129aa69b95b9eee3, lqi = 126, ch = 15)
 [M0] [00000000.589][PLATFORM]      ZbMonitorHandleTransKeyInd : Adding network key, sequence number = 0
 [M0] [00000000.589][PLATFORM]                ZbZdoDeviceAnnce : Sending Device_Annce for 0x0f8f
[M4 APPLICATION] ZbStartup Callback (status = 0x00)
[M4 APPLICATION] Startup done !

 [M0] [00000002.137][PLATFORM]              zcl_handle_command : ZCL Command: cluster=0x0000, dst=0x01, fc_manuf=0, fc_dir=0, cmd=0x00
 [M0] [00000002.138][PLATFORM]             ZbZclHandleReadAttr : Handling ZCL Read of cl = 0x0000, attr = 0x0004
 [M0] [00000002.138][PLATFORM]             ZbZclHandleReadAttr : Handling ZCL Read of cl = 0x0000, attr = 0x0005

It seems to me that HA does not see the device that join the network and so does not interrogate the device on the cluster's details... (for the cases that fails, not this one)

Gunlek commented 3 months ago

Actually, I think your device is already associated:

[00000000.017][PLATFORM]               nwk_join_try_next : Associating (src = 0x0080e125006f0c7e) to 0x0000 (epid = 0x129aa69b95b9eee3, lqi = 171, ch = 15)
 [M0] 

The coordinator is receiving MAC poll messages from 0x11BA:

2024-03-01 13:39:26.007 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 18, 'payload_length': 11, 'src_addr': DeconzAddress(address_mode=<AddressMode.IEEE: 3>, address=00:80:e1:25:00:6f:0c:7e), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 39)
2024-03-01 13:39:27.707 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 40)
2024-03-01 13:39:31.376 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 41)
2024-03-01 13:39:31.898 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 42)
2024-03-01 13:39:32.424 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 43)
2024-03-01 13:39:32.947 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.mac_poll{'status': <Status.SUCCESS: 0>, 'frame_length': 12, 'payload_length': 5, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x11BA), 'lqi': 255, 'rssi': -56, 'life_time': None, 'device_timeout': None} (seq 44)

Can you upload a PCAP of the device joining and a few of the indefinite looping scenarios?

There are no known issues with the Conbee II working with any other production devices so I may have to lean towards there being issues on the dev kit side.

What I call "infinite looping" scenario is in fact "infinite interview phase" which correspond to the one described in the original post. In fact, I have 3 scenarios:

Of course, in any of this cases, I'm in pairing mode both on STM32 and HA, I consider that Fail STM32/Fail HA scenario is probably due to insuffisant linbk quality from STM32 perspective and then I exclude this scenario from my issue up to now.

puddly commented 3 months ago

Setting up a PCAP on device side is - as far as I know - not possible due to the fact that STM32 is an embedded system's software...

Right. I meant with a sniffer, like a Silicon Labs radio (e.g. SkyConnect, HUSBZB-1, Sonoff stick) or a Conbee II flashed with sniffer firmware.

For ZHA to detect that your device has joined the network, it must announce itself (as it does in your log):

2024-03-03 20:15:38.590 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 3, 19, 15, 38, 590105, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0F8F), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.Broadcast: 15>, address=<BroadcastAddress.RX_ON_WHEN_IDLE: 65533>), dst_ep=0, source_route=None, extended_timeout=False, tsn=None, profile_id=0, cluster_id=19, data=Serialized[b'\x00\x8f\x0f~\x0co\x00%\xe1\x80\x00\x84'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=255, rssi=-70)
2024-03-03 20:15:38.592 INFO (MainThread) [zigpy.application] New device 0x0f8f (00:80:e1:25:00:6f:0c:7e) joined the network

An RSSI of -70 is quite low.

Gunlek commented 3 months ago

Setting up a PCAP on device side is - as far as I know - not possible due to the fact that STM32 is an embedded system's software...

Right. I meant with a sniffer, like a Silicon Labs radio (e.g. SkyConnect, HUSBZB-1, Sonoff stick) or a Conbee II flashed with sniffer firmware.

For ZHA to detect that your device has joined the network, it must announce itself (as it does in your log):

2024-03-03 20:15:38.590 DEBUG (MainThread) [zigpy.application] Received a packet: ZigbeePacket(timestamp=datetime.datetime(2024, 3, 3, 19, 15, 38, 590105, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0F8F), src_ep=0, dst=AddrModeAddress(addr_mode=<AddrMode.Broadcast: 15>, address=<BroadcastAddress.RX_ON_WHEN_IDLE: 65533>), dst_ep=0, source_route=None, extended_timeout=False, tsn=None, profile_id=0, cluster_id=19, data=Serialized[b'\x00\x8f\x0f~\x0co\x00%\xe1\x80\x00\x84'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=255, rssi=-70)
2024-03-03 20:15:38.592 INFO (MainThread) [zigpy.application] New device 0x0f8f (00:80:e1:25:00:6f:0c:7e) joined the network

An RSSI of -70 is quite low.

As a follow up, I'm waiting for a sniffing device, I'm still working on the issue. I tested with MQTT and same kind of issue, I want to ensure if it is device related or HA related and will post a follow up once I have any clue ! I'm also open to any new idea of course !

Gunlek commented 3 months ago

Please find below the PCAP of a successful joining from STM32 perspective but no device added in HA: image

I will try to get another result with both successful once I get it

Gunlek commented 3 months ago

Here is another PCAP with successful on both side: image

Gunlek commented 3 months ago

Here's a zip with the two .pcapng recorded files

filtered_pcap.zip

Gunlek commented 3 months ago

Pairing works perfectly under Jeedom using conbee 2 and zigpy driver

Also discovered that only "force remove" cause this issue. Removing the device from HA with the device still powered on cause no issue. This lead me to think about a refresh network issue...

issue-triage-workflows[bot] commented 1 week ago

There hasn't been any activity on this issue recently. Due to the high number of incoming GitHub notifications, we have to clean some of the old issues, as many of them have already been resolved with the latest updates. Please make sure to update to the latest Home Assistant version and check if that solves the issue. Let us know if that works for you by adding a comment 👍 This issue has now been marked as stale and will be closed if no further activity occurs. Thank you for your contributions.