Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Unknown command received: CommandId.undefined_0x81: 129 #258

Open
rrooggiieerr opened this issue Jun 16, 2024 · 9 comments
Open

Unknown command received: CommandId.undefined_0x81: 129 #258

rrooggiieerr opened this issue Jun 16, 2024 · 9 comments

Comments

@rrooggiieerr
Copy link

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')
@rrooggiieerr rrooggiieerr changed the title Unknown commands received: CommandId.undefined_0x81: 129 Unknown command received: CommandId.undefined_0x81: 129 Jun 16, 2024
@puddly
Copy link
Contributor

puddly commented Jun 16, 2024

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
Copy link
Author

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
Copy link
Contributor

puddly commented Jun 16, 2024

You can ZIP and attach the whole log here

@rrooggiieerr
Copy link
Author

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
Copy link
Author

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
Copy link
Contributor

puddly commented Jun 17, 2024

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
Copy link
Author

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
Copy link
Author

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
Copy link
Contributor

puddly commented Jun 17, 2024

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@rrooggiieerr @puddly