ValueError(f"Data is too short to contain {byte_size} bytes") on IEEE Addr Request

[pipiche38]

Strange issue . The Sniff trace seems to be good, why is zigpy seeing errors !!!

2022-06-30 19:50:56,654 DEBUG   :Received command: ZDO.SrcRtgInd.Callback(DstAddr=0xFFA7, Relays=[0xCA65])
2022-06-30 19:50:56,663 DEBUG   :get_device raise KeyError ieee: None nwk: ffa7 !!
2022-06-30 19:50:56,666 DEBUG   :Device with NWK 0xFFA7 not in database
2022-06-30 19:50:56,672 DEBUG   :Sending request: ZDO.IEEEAddrReq.Req(NWK=0xFFA7, RequestType=<AddrRequestType.SINGLE: 0>, StartIndex=0)
2022-06-30 19:50:56,687 DEBUG   :Received command: ZDO.SrcRtgInd.Callback(DstAddr=0xFFA7, Relays=[0xCA65])
2022-06-30 19:50:56,726 DEBUG   :Received command: ZDO.IEEEAddrReq.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-30 19:50:56,731 DEBUG   :Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=15, SrcAddr=0xFFA7, SrcEndpoint=35, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=160, SecurityUse=<Bool.false: 0>, TimeStamp=11327531, TSN=0, Data=b'\x18\xAF\x0A\x55\x00\x10\x00\x6F\x00\x18\x00', MacSrcAddr=0xCA65, MsgResultRadius=28)
2022-06-30 19:50:56,737 DEBUG   :Received command: ZDO.IEEEAddrRsp.Callback(Status=<Status.SUCCESS: 0>, IEEE=00:15:bc:00:1a:01:aa:27, NWK=0xFFA7, NumAssoc=0, Index=0, Devices=[])
2022-06-30 19:50:56,743 DEBUG   :get_device raise KeyError ieee: 0015bc001a01aa27 nwk: None !!
2022-06-30 19:50:56,746 DEBUG   :Treating unknown device as a new join
2022-06-30 19:50:56,749 DEBUG   :get_device raise KeyError ieee: 0015bc001a01aa27 nwk: None !!
2022-06-30 19:50:56,751 DEBUG   :handle_join waiting 1s for zigbee initialisation
2022-06-30 19:50:57,754 INFO    :New device 0xffa7 (00:15:bc:00:1a:01:aa:27) joined the network
2022-06-30 19:50:57,773 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0xFFA7, IsBroadcast=<Bool.false: 0>, ClusterId=32769, SecurityUse=0, TSN=3, MacDst=0x0000, Data=b'\x00\x27\xAA\x01\x1A\x00\xBC\x15\x00\xA7\xFF')
2022-06-30 19:50:57,781 DEBUG   :Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=1026, SrcAddr=0xFFA7, SrcEndpoint=38, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=160, SecurityUse=<Bool.false: 0>, TimeStamp=11329582, TSN=0, Data=b'\x18\xB0\x0A\x00\x00\x29\xE9\x09', MacSrcAddr=0xCA65, MsgResultRadius=28)
2022-06-30 19:50:57,788 DEBUG   :Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=1280, SrcAddr=0xFFA7, SrcEndpoint=35, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=156, SecurityUse=<Bool.false: 0>, TimeStamp=11358056, TSN=0, Data=b'\x19\xB1\x00\x30\x00\x00\x00\xFF\xFF', MacSrcAddr=0xCA65, MsgResultRadius=28)
2022-06-30 19:50:57,793 DEBUG   :Received command: AF.IncomingMsg.Callback(GroupId=0x0000, ClusterId=1024, SrcAddr=0xFFA7, SrcEndpoint=39, DstEndpoint=1, WasBroadcast=<Bool.false: 0>, LQI=156, SecurityUse=<Bool.false: 0>, TimeStamp=11386554, TSN=0, Data=b'\x18\xB2\x0A\x00\x00\x21\x6E\x18', MacSrcAddr=0xCA65, MsgResultRadius=28)
2022-06-30 19:50:57,804 DEBUG   :[0x0000:zdo] ZDO request ZDOCmd.IEEE_addr_req: [0xFFA7, 0, 0]
2022-06-30 19:50:57,811 DEBUG   :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.Broadcast: 15>, address=0xFFFD), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=1, TSN=15, Options=<TransmitOptions.NONE: 0>, Radius=0, Data=b'\x00\xA7\xFF\x00\x00')
2022-06-30 19:50:57,853 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-30 19:50:57,891 DEBUG   :Received command: ZDO.IEEEAddrRsp.Callback(Status=<Status.SUCCESS: 0>, IEEE=00:15:bc:00:1a:01:aa:27, NWK=0xFFA7, NumAssoc=26, Index=0, Devices=[])
2022-06-30 19:50:57,899 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0xCA65, IsBroadcast=<Bool.false: 0>, ClusterId=32769, SecurityUse=0, TSN=0, MacDst=0x0000, Data=b'\x00\x27\xAA\x01\x1A\x00\xBC\x15\x00\xA7\xFF')
2022-06-30 19:50:58,125 ERROR   :Failed to parse message (b'0081ffa7') on cluster 32769, because Data is too short to contain 1 bytes
2022-06-30 19:50:58,131 DEBUG   :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x0000), DstEndpoint=0, DstPanId=0x0000, SrcEndpoint=0, ClusterId=32769, TSN=16, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x00\x81\xFF\xA7')
2022-06-30 19:50:58,154 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-06-30 19:50:58,157 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x0000, IsBroadcast=<Bool.false: 0>, ClusterId=32769, SecurityUse=0, TSN=0, MacDst=0x0000, Data=b'\x81\xFF\xA7')
2022-06-30 19:50:58,162 ERROR   :Task exception was never retrieved
future: <Task finished name='Task-52' coro=<ControllerApplication.on_zdo_message() done, defined at /var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/zigbee/application.py:519> exception=ValueError('Data is too short to contain 1 bytes')>
Traceback (most recent call last):
  File "/usr/lib/python3.9/asyncio/tasks.py", line 256, in __step
    result = coro.send(None)
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy_znp/zigbee/application.py", line 527, in on_zdo_message
    args, data = list_deserialize(data, types)
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy/types/__init__.py", line 9, in deserialize
    value, data = type_.deserialize(data)
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy/types/basic.py", line 682, in deserialize
    item, data = cls._item_type.deserialize(data)
  File "/var/lib/domoticz/plugins/Domoticz-Zigbee/zigpy/types/basic.py", line 147, in deserialize
    raise ValueError(f"Data is too short to contain {byte_size} bytes")

[puddly]

Post the PCAP, there seem to be multiple responses.

[pipiche38]

Puddly when the zigpy layer doesn the ZDO.IEEEAddrReq.Req() it looks like when the response is received it is only handle by the zigpy layer and not forwarded above to the plugin ?

Would it be possible to get it as well ?

[puddly]

You should be able to subscribe to an zdo_ieee_addr_rsp event: https://github.com/zigpy/zigpy/blob/ada23ea7e7e466ef00b845f77e0e935fad877fcf/zigpy/zdo/__init__.py#L84-L90

[badzz]

should we add a listener using add_listener ?

https://github.com/zigpy/zigpy/blob/494e13e86b908e1d1bbb3f3f29087964df8702dd/zigpy/util.py#L34

[puddly]

Yes.

[pipiche38]

You should be able to subscribe to an zdo_ieee_addr_rsp event: https://github.com/zigpy/zigpy/blob/ada23ea7e7e466ef00b845f77e0e935fad877fcf/zigpy/zdo/__init__.py#L84-L90

I'm not sure this is what you want.
When I do an IEEE Nwk addr request I got the response back, and this works well.
The issue, is when zigpy detect that a nwkid doesn't exist it does a IEEE Nwk req and in that case I don't get the response . This is my issue .

[pipiche38]

+1