search

zigpy / zigpy-deconz

A library which communicates with Deconz radios for zigpy
GNU General Public License v3.0
86 stars 20 forks source link

Unknown command received: CommandId.undefined_0x81: 129 #258

Open rrooggiieerr opened 4 weeks ago

rrooggiieerr commented 4 weeks ago

I'm getting these messages a couple of times per hour. Haven't figured out which device is sending it or what message 0x81 is. Payload always seems to be the same

2024-06-16 02:49:27.973 WARNING (MainThread) [zigpy_deconz.api] Unknown command received: Command(command_id=<CommandId.undefined_0x81: 129>, seq=130, payload=b'\x03\x00\x03\x00\x88\xcd\xc2\x93')
2024-06-16 02:49:36.446 WARNING (MainThread) [zigpy_deconz.api] Unknown command received: Command(command_id=<CommandId.undefined_0x81: 129>, seq=130, payload=b'\x03\x00\x03\x00\x88\xcd\xc2\x93')
2024-06-16 03:11:29.226 WARNING (MainThread) [zigpy_deconz.api] Unknown command received: Command(command_id=<CommandId.undefined_0x81: 129>, seq=130, payload=b'\x03\x00\x03\x00\x88\xcd\xc2\x93')
2024-06-16 03:27:47.148 WARNING (MainThread) [zigpy_deconz.api] Unknown command received: Command(command_id=<CommandId.undefined_0x81: 129>, seq=130, payload=b'\x03\x00\x03\x00\x88\xcd\xc2\x93')
puddly commented 4 weeks ago

Can you enable ZHA debugging and post a log containing a few of these warnings?

deCONZ was recently open sourced and I can't find any mention of a command 0x81: https://github.com/dresden-elektronik/deconz/blob/d9ddb8a8731301ac61e44434f031f7cf5651e3ca/src/common/zm_protocol.h#L106

rrooggiieerr commented 4 weeks ago

Enabling ZHA debugging gives a gazillion of log messages. Anything specific I should look for? Or how I can dail down the logging? Should debug logging for zigpy-deconz be sufficient?

puddly commented 4 weeks ago

You can ZIP and attach the whole log here

rrooggiieerr commented 4 weeks ago

I think this part of the log contains the relevant info

2024-06-16 09:54:35.908 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e64000700aa00
2024-06-16 09:54:36.332 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 100)
2024-06-16 09:54:36.542 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e65000700aa00
2024-06-16 09:54:36.544 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 101)
2024-06-16 09:54:36.544 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e66000700aa00
2024-06-16 09:54:36.545 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 102)
2024-06-16 09:54:38.419 DEBUG (MainThread) [zigpy_deconz.api] Sending CommandId.aps_data_indication{'flags': <DataIndicationFlags.Always_Use_NWK_Source_Addr: 1>} (seq=100)
2024-06-16 09:54:38.420 DEBUG (MainThread) [zigpy_deconz.uart] Send: 1764000800010001
2024-06-16 09:54:58.084 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0xCEA7:1:0x0702]: async_update
2024-06-16 09:54:58.319 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0xCEA7:1:0x0702]: Reading attributes in chunks: ['current_summ_delivered', 'status']
2024-06-16 09:54:58.484 DEBUG (MainThread) [zigpy.zcl] [0xCEA7:1:0x0702] 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=35, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Client_to_Server: 0>)
2024-06-16 09:54:58.610 DEBUG (MainThread) [zigpy.zcl] [0xCEA7:1:0x0702] Sending request: Read_Attributes(attribute_ids=[0, 512])
2024-06-16 09:54:58.676 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending packet: ZigbeePacket(timestamp=datetime.datetime(2024, 6, 16, 7, 54, 58, 676287, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0xCEA7), dst_ep=1, source_route=None, extended_timeout=False, tsn=35, profile_id=260, cluster_id=1794, data=Serialized[b'\x00#\x00\x00\x00\x00\x02'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-06-16 09:54:59.905 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x55F7:1:0x0b04]: async_update
2024-06-16 09:54:59.906 DEBUG (MainThread) [homeassistant.components.zha.core.cluster_handlers] [0x55F7:1:0x0b04]: Reading attributes in chunks: ['active_power', 'rms_current', 'rms_voltage']
2024-06-16 09:54:59.908 DEBUG (MainThread) [zigpy.zcl] [0x55F7:1:0x0b04] 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=253, command_id=<GeneralCommand.Read_Attributes: 0>, *direction=<Direction.Client_to_Server: 0>)
2024-06-16 09:54:59.913 DEBUG (MainThread) [zigpy.zcl] [0x55F7:1:0x0b04] Sending request: Read_Attributes(attribute_ids=[1291, 1288, 1285])
2024-06-16 09:54:59.914 DEBUG (MainThread) [zigpy_deconz.zigbee.application] Sending packet: ZigbeePacket(timestamp=datetime.datetime(2024, 6, 16, 7, 54, 59, 914595, tzinfo=datetime.timezone.utc), src=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x0000), src_ep=1, dst=AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x55F7), dst_ep=1, source_route=None, extended_timeout=False, tsn=253, profile_id=260, cluster_id=2820, data=Serialized[b'\x00\xfd\x00\x0b\x05\x08\x05\x05\x05'], tx_options=<TransmitOptions.NONE: 0>, radius=0, non_member_radius=0, lqi=None, rssi=None)
2024-06-16 09:55:12.219 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x1764002b0024002a02000001025b5501040100ef0d0009c50200276d0200040000000000afff08008b02d6
2024-06-16 09:55:12.235 DEBUG (MainThread) [zigpy_deconz.api] Received command CommandId.aps_data_indication{'status': <Status.SUCCESS: 0>, 'frame_length': 43, 'payload_length': 36, 'device_state': DeviceState(network_state=<NetworkState2.CONNECTED: 2>, device_state=<DeviceStateFlags.APSDE_DATA_INDICATION|APSDE_DATA_REQUEST_FREE_SLOTS_AVAILABLE: 10>), 'dst_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x0000), 'dst_ep': 1, 'src_addr': DeconzAddress(address_mode=<AddressMode.NWK: 2>, address=0x555B), 'src_ep': 1, 'profile_id': 260, 'cluster_id': 61184, 'asdu': b"\t\xc5\x02\x00'm\x02\x00\x04\x00\x00\x00\x00", 'reserved1': 0, 'reserved2': 175, 'lqi': 255, 'reserved3': 8, 'reserved4': 0, 'reserved5': 139, 'reserved6': 2, 'rssi': -42} (seq 100)
2024-06-16 09:55:12.244 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x0e65000700aa00
2024-06-16 09:55:12.308 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 101)
2024-06-16 09:55:12.311 DEBUG (MainThread) [zigpy_deconz.uart] Frame received: 0x81820300030088cdc293
2024-06-16 09:55:12.312 WARNING (MainThread) [zigpy_deconz.api] Unknown command received: Command(command_id=<CommandId.undefined_0x81: 129>, seq=130, payload=b'\x03\x00\x03\x00\x88\xcd\xc2\x93')
rrooggiieerr commented 3 weeks ago

I'm not exactly sure how this command could have been triggered, but I'm suspecting one of my custom HA integrations was doing blocking IO which somehow corrupted some communication ending up in this command. I've upgraded some of my custom integrations and the issue has not shown up since.

puddly commented 3 weeks ago

Very strange. The UART buffer cannot be corrupted by event loop stuttering: it's something handled entirely by the OS. Python just schedules writes and receives read data, it's not doing anything low-level. Also, the deCONZ UART protocol has checksums so (single) bit flips should not be possible.

rrooggiieerr commented 3 weeks ago

Also that it always the same payload is strange to me. If it would be corrupted data I would expect the payload to be random

But I actually still get the messages, they're not entirely gone but is seems to be less frequent. Only 6 times in the las 8 hours

rrooggiieerr commented 3 weeks ago

I also see a lot of these messages:

2024-06-17 14:14:54.421 WARNING (MainThread) [zigpy.application] Unknown device AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x48E6)
2024-06-17 14:18:06.432 WARNING (MainThread) [zigpy.application] Unknown device AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x48E6)
2024-06-17 14:32:36.499 WARNING (MainThread) [zigpy.application] Unknown device AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x48E6)
2024-06-17 14:47:06.559 WARNING (MainThread) [zigpy.application] Unknown device AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x48E6)
2024-06-17 14:52:11.479 WARNING (MainThread) [zigpy.application] Unknown device AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x48E6)
2024-06-17 14:55:10.760 WARNING (MainThread) [zigpy.application] Unknown device AddrModeAddress(addr_mode=<AddrMode.NWK: 2>, address=0x48E6)
puddly commented 3 weeks ago

Not a problem. There is a device on your network that is sending data but it cannot be interviewed. It's likely an Aqara sensor.