zigpy / zigpy-znp

TI CC2531, CC13x2, CC26x2 radio support for Zigpy and ZHA
GNU General Public License v3.0
144 stars 40 forks source link

DeliveryError : Request failed after 5 attempts: <Status.MAC_NO_ACK: 233> #189

Closed pipiche38 closed 1 year ago

pipiche38 commented 1 year ago

Time to time for no good reason, message are failing to be sent.

2022-10-22 14:43:25,480 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-22 14:43:26,332 DEBUG   :Received command: AF.DataConfirm.Callback(Status=<Status.MAC_TRANSACTION_EXPIRED: 240>, Endpoint=1, TSN=3)
2022-10-22 14:43:26,336 DEBUG   :Request failed (Unsuccessful request status code: <Status.MAC_TRANSACTION_EXPIRED: 240>), retry attempt 1 of 5
2022-10-22 14:43:27,074 DEBUG   :Received command: ZDO.BindRsp.Callback(Src=0x1672, Status=<Status.SUCCESS: 0>)
2022-10-22 14:43:27,076 DEBUG   :Command was not handled
2022-10-22 14:43:27,079 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x1672, IsBroadcast=<Bool.false: 0>, ClusterId=32801, SecurityUse=0, TSN=3, MacDst=0x0000, Data=b'\x00')
2022-10-22 14:43:27,088 DEBUG   : [ ZigpyCom_4 12285] handle_message Sender: 1672 frame for plugin: 018002001eff0000008021000002167202000003008603
2022-10-22 14:43:27,844 DEBUG   :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x1672), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=1, TSN=3, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x10\x03\x06\x00\x21\x00\x20\x10\x0E\xC0\xA8\x01')
2022-10-22 14:43:27,860 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-22 14:43:28,048 DEBUG   :Received command: ZDO.BindRsp.Callback(Src=0x1672, Status=<Status.SUCCESS: 0>)
2022-10-22 14:43:28,049 DEBUG   :Command was not handled
2022-10-22 14:43:28,052 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x1672, IsBroadcast=<Bool.false: 0>, ClusterId=32801, SecurityUse=0, TSN=3, MacDst=0x0000, Data=b'\x00')
2022-10-22 14:43:28,059 DEBUG   : [ ZigpyCom_4 12285] handle_message Sender: 1672 frame for plugin: 018002001eff0000008021000002167202000003008603
2022-10-22 14:43:28,429 DEBUG   :Received command: AF.DataConfirm.Callback(Status=<Status.MAC_TRANSACTION_EXPIRED: 240>, Endpoint=1, TSN=3)
2022-10-22 14:43:28,434 DEBUG   :Sending request: UTIL.AssocGetWithAddress.Req(IEEE=3c:6a:2c:ff:fe:d1:2d:e6, NWK=0x0000)
2022-10-22 14:43:28,460 DEBUG   :Received command: UTIL.AssocGetWithAddress.Rsp(Device=Device(shortAddr=0x1672, addrIdx=21, nodeRelation=<NodeRelation.CHILD_RFD: 1>, devStatus=8, assocCnt=0, age=0, linkInfo=LinkInfo(txCounter=0, txCost=1, rxLqi=133, inKeySeqNum=0, inFrmCntr=0, txFailure=65535), endDev=AgingEndDevice(endDevCfg=255, deviceTimeout=4294967295), timeoutCounter=4294967295, keepaliveRcv=255, ctrl=255))
2022-10-22 14:43:28,464 DEBUG   :Sending request: UTIL.AssocRemove.Req(IEEE=3c:6a:2c:ff:fe:d1:2d:e6)
2022-10-22 14:43:28,475 DEBUG   :Received command: UTIL.AssocRemove.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-22 14:43:28,479 DEBUG   :Sending request: ZDO.ExtRouteDisc.Req(Dst=0x1672, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2022-10-22 14:43:28,489 DEBUG   :Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-22 14:43:29,793 DEBUG   :Request failed (Unsuccessful request status code: <Status.MAC_TRANSACTION_EXPIRED: 240>), retry attempt 2 of 5
2022-10-22 14:43:30,085 DEBUG   :Received command: ZDO.BindRsp.Callback(Src=0x1672, Status=<Status.SUCCESS: 0>)
2022-10-22 14:43:30,087 DEBUG   :Command was not handled
2022-10-22 14:43:30,089 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x1672, IsBroadcast=<Bool.false: 0>, ClusterId=32801, SecurityUse=0, TSN=4, MacDst=0x0000, Data=b'\x00')
2022-10-22 14:43:30,097 DEBUG   : [ ZigpyCom_4 12285] handle_message Sender: 1672 frame for plugin: 018002001eff0000008021000002167202000004008603
2022-10-22 14:43:30,300 DEBUG   :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x1672), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=1, TSN=3, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x10\x03\x06\x00\x21\x00\x20\x10\x0E\xC0\xA8\x01')
2022-10-22 14:43:30,325 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-22 14:43:30,404 DEBUG   :Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=3)
2022-10-22 14:43:30,408 DEBUG   :Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 3 of 5
2022-10-22 14:43:30,914 DEBUG   :Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x1672, DstEndpoint=1, SrcEndpoint=1, ClusterId=1, TSN=3, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, SourceRoute=[], Data=b'\x10\x03\x06\x00\x21\x00\x20\x10\x0E\xC0\xA8\x01')
2022-10-22 14:43:30,938 DEBUG   :Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-22 14:43:31,016 DEBUG   :Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=3)
2022-10-22 14:43:31,021 DEBUG   :Sending request: ZDO.ExtRouteDisc.Req(Dst=0x1672, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2022-10-22 14:43:31,034 DEBUG   :Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-22 14:43:32,338 DEBUG   :Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 4 of 5
2022-10-22 14:43:32,843 DEBUG   :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x1672), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=1, TSN=3, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x10\x03\x06\x00\x21\x00\x20\x10\x0E\xC0\xA8\x01')
2022-10-22 14:43:32,868 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-22 14:43:32,948 DEBUG   :Received command: AF.DataConfirm.Callback(Status=<Status.MAC_NO_ACK: 233>, Endpoint=1, TSN=3)
2022-10-22 14:43:32,952 DEBUG   :Request failed (Unsuccessful request status code: <Status.MAC_NO_ACK: 233>), retry attempt 5 of 5
2022-10-22 14:43:33,456 DEBUG   :Sending request: UTIL.AssocAdd.Req(NWK=0x1672, IEEE=3c:6a:2c:ff:fe:d1:2d:e6, NodeRelation=<NodeRelation.CHILD_RFD: 1>)
2022-10-22 14:43:33,467 DEBUG   :Received command: UTIL.AssocAdd.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-22 14:43:33,489 INFO    : [ ZigpyCom_4 12285] process_raw_command - DeliveryError : Request failed after 5 attempts: <Status.MAC_NO_ACK: 233>

I'm attaching as well a more logs (which start from the beginning of the pairing of that device) znp-error.zip

I'm also attaching a sniff corresponding to the same period (transction key: 846624840d2c90ee601725a232976a10) CMS323-znp-error.pcapng.zip

Attached is the startup phase, so I believe you can get all information related to the Coordinator ( which is a SONOFF) znp-startup.zip

MattWestb commented 1 year ago

Sorry for spamming but i finding the sniff very interesting !! Device have getting network key and is sending one Device Announcement:

Frame 31: 65 bytes on wire (520 bits), 65 bytes captured (520 bits) on interface -, id 0
IEEE 802.15.4 Data, Dst: 0x0000, Src: 0x1672
ZigBee Network Layer Data, Dst: Broadcast, Src: 0x1672
    Frame Control Field: 0x1208, Frame Type: Data, Discover Route: Suppress, Security, Extended Source Data
        .... .... .... ..00 = Frame Type: Data (0x0)
        .... .... ..00 10.. = Protocol Version: 2
        .... .... 00.. .... = Discover Route: Suppress (0x0)
        .... ...0 .... .... = Multicast: False
        .... ..1. .... .... = Security: True
        .... .0.. .... .... = Source Route: False
        .... 0... .... .... = Destination: False
        ...1 .... .... .... = Extended Source: True
        ..0. .... .... .... = End Device Initiator: False
    Destination: 0xfffd
    Source: 0x1672
    Radius: 30
    Sequence Number: 85
    Extended Source: IEEERegi_ff:fe:d1:2d:e6 (3c:6a:2c:ff:fe:d1:2d:e6)
    ZigBee Security Header
ZigBee Application Support Layer Data, Dst Endpt: 0, Src Endpt: 0
    Frame Control Field: Data (0x08)
    Destination Endpoint: 0
    Device Announcement (Cluster ID: 0x0013)
    Profile: ZigBee Device Profile (0x0000)
    Source Endpoint: 0
    Counter: 19
ZigBee Device Profile, Device Announcement, Nwk Addr: 0x1672, Ext Addr: IEEERegi_ff:fe:d1:2d:e6
    Sequence Number: 132
    Nwk Addr of Interest: 0x1672
    Extended Address: IEEERegi_ff:fe:d1:2d:e6 (3c:6a:2c:ff:fe:d1:2d:e6)
    Capability Information: 0x80
        .... ...0 = Alternate Coordinator: False
        .... ..0. = Full-Function Device: False
        .... .0.. = AC Power: False
        .... 0... = Rx On When Idle: False
        .0.. .... = Security Capability: False
        1... .... = Allocate Short Address: True

Its saying the joining device is:

    .... ..0. = Full-Function Device: False
    .... .0.. = AC Power: False
    .... 0... = Rx On When Idle: False
    .0.. .... = Security Capability: False

One real sleeper and is not AC powered and that shall the coordinator now knowing.

Then the coordinator is requesting node description and getting replay from the device:

Frame 137: 62 bytes on wire (496 bits), 62 bytes captured (496 bits) on interface -, id 0
IEEE 802.15.4 Data, Dst: 0x0000, Src: 0x1672
ZigBee Network Layer Data, Dst: 0x0000, Src: 0x1672
    Frame Control Field: 0x0208, Frame Type: Data, Discover Route: Suppress, Security Data
        .... .... .... ..00 = Frame Type: Data (0x0)
        .... .... ..00 10.. = Protocol Version: 2
        .... .... 00.. .... = Discover Route: Suppress (0x0)
        .... ...0 .... .... = Multicast: False
        .... ..1. .... .... = Security: True
        .... .0.. .... .... = Source Route: False
        .... 0... .... .... = Destination: False
        ...0 .... .... .... = Extended Source: False
        ..0. .... .... .... = End Device Initiator: False
    Destination: 0x0000
    Source: 0x1672
    Radius: 30
    Sequence Number: 103
    [Extended Source: IEEERegi_ff:fe:d1:2d:e6 (3c:6a:2c:ff:fe:d1:2d:e6)]
    [Origin: 31]
    ZigBee Security Header
ZigBee Application Support Layer Data, Dst Endpt: 0, Src Endpt: 0
    Frame Control Field: Data (0x40)
    Destination Endpoint: 0
    Node Descriptor Response (Cluster ID: 0x8002)
    Profile: ZigBee Device Profile (0x0000)
    Source Endpoint: 0
    Counter: 27
ZigBee Device Profile, Node Descriptor Response, Rev: 22, Nwk Addr: 0x1672, Status: Success
    Sequence Number: 2
    Status: Success (0)
    Nwk Addr of Interest: 0x1672
    Node Descriptor
        .... .... .... .010 = Type: 2 (End Device)
        .... .... .... 0... = Complex Descriptor: False
        .... .... ...0 .... = User Descriptor: False
        .... 0... .... .... = 868MHz BPSK Band: False
        ..0. .... .... .... = 902MHz BPSK Band: False
        .1.. .... .... .... = 2.4GHz OQPSK Band: True
        0... .... .... .... = EU Sub-GHz FSK Band: False
        Capability Information: 0x80
            .... ...0 = Alternate Coordinator: False
            .... ..0. = Full-Function Device: False
            .... .0.. = AC Power: False
            .... 0... = Rx On When Idle: False
            .0.. .... = Security Capability: False
            1... .... = Allocate Short Address: True
        Manufacturer Code: 0x113c
        Max Buffer Size: 82
        Max Incoming Transfer Size: 82
        Server Flags: 0x2c00
            .... .... .... ...0 = Primary Trust Center: False
            .... .... .... ..0. = Backup Trust Center: False
            .... .... .... .0.. = Primary Binding Table Cache: False
            .... .... .... 0... = Backup Binding Table Cache: False
            .... .... ...0 .... = Primary Discovery Cache: False
            .... .... ..0. .... = Backup Discovery Cache: False
            .... .... .0.. .... = Network Manager: False
            0010 110. .... .... = Stack Compliance Revision: 22
        Max Outgoing Transfer Size: 82
        Descriptor Capability Field: 0x00
            .... ...0 = Extended Active Endpoint List Available: False
            .... ..0. = Extended Simple Descriptor List Available: False

Its saying:.... .... .... .010 = Type: 2 (End Device) plus the same as the device accouterments = sleeping end device.

And the joining device is saying its one Zigbee 3 device and like doing all right so it sending one End Device Timeout Request (acked in 154) and waiting for one End Device Timeout Response that the parent router (coordinator) is not sending. The device is pulling its parent for getting the response but is not coming (frame 35 to 55 and every frames is acked in 154).

All other is OK to this point.

No. Time    PAN Protocol    IEEE Src    IEEE Dst    Zigbee Src  Zigbee Dst  ZBN Dst Group Nr    ZBN Seq ZBA Seq ZDP Seq Nwk Seq Src EP  Dst EP  Info
29  12:43:04,002984 0x12af  ZigBee  0x0000  0x1672  0x0000  0x1672  0x1672      203 121     41          Transport Key
30  12:43:04,005704 0x12af  IEEE 802.15.4   0x1672  0x0000                              41          Ack
31  12:43:04,019241 0x12af  ZigBee ZDP  0x1672  0x0000  0x1672  Broadcast   0xfffd      85  19  132 109 0   0   Device Announcement, Nwk Addr: 0x1672, Ext Addr: IEEERegi_ff:fe:d1:2d:e6
32  12:43:04,021705 0x12af  IEEE 802.15.4   0x0000  0x1672                              109         Ack
33  12:43:04,024941 0x12af  ZigBee  0x1672  0x0000  0x1672  0x0000  0x0000      86          110         End Device Timeout Request
34  12:43:04,027117 0x12af  IEEE 802.15.4   0x0000  0x1672                              110         Ack
35  12:43:04,029349 0x12af  IEEE 802.15.4   0x1672  0x0000  0x1672  0x0000                      111         Data Request
36  12:43:04,030115 0x12af  IEEE 802.15.4   0x0000  0x1672                              111         Ack
37  12:43:04,040043 0x12af  ZigBee ZDP  0x0000  0xffff  0x1672  Broadcast   0xfffd      85  19  132 42  0   0   Device Announcement, Nwk Addr: 0x1672, Ext Addr: IEEERegi_ff:fe:d1:2d:e6
38  12:43:04,124140 0x12af  IEEE 802.15.4   0x1672  0x0000  0x1672  0x0000                      112         Data Request
39  12:43:04,124908 0x12af  IEEE 802.15.4   0x0000  0x1672                              112         Ack
40  12:43:04,420514 0x12af  IEEE 802.15.4   0x1672  0x0000  0x1672  0x0000                      113         Data Request
41  12:43:04,421282 0x12af  IEEE 802.15.4   0x0000  0x1672                              113         Ack
42  12:43:04,433623 0x12af  IEEE 802.15.4   0x1672  0x0000  0x1672  0x0000                      113         Data Request
43  12:43:04,434391 0x12af  IEEE 802.15.4   0x0000  0x1672                              113         Ack
44  12:43:04,724612 0x12af  IEEE 802.15.4   0x1672  0x0000  0x1672  0x0000                      114         Data Request
45  12:43:04,725380 0x12af  IEEE 802.15.4   0x0000  0x1672                              114         Ack
46  12:43:05,024664 0x12af  IEEE 802.15.4   0x1672  0x0000  0x1672  0x0000                      115         Data Request
47  12:43:05,025432 0x12af  IEEE 802.15.4   0x0000  0x1672                              115         Ack
48  12:43:05,027378 0x12af  IEEE 802.15.4   0x1672  0x0000  0x1672  0x0000                      116         Data Request
49  12:43:05,028146 0x12af  IEEE 802.15.4   0x0000  0x1672                              116         Ack
50  12:43:05,330494 0x12af  IEEE 802.15.4   0x1672  0x0000  0x1672  0x0000                      117         Data Request
51  12:43:05,331262 0x12af  IEEE 802.15.4   0x0000  0x1672                              117         Ack
52  12:43:06,033660 0x12af  IEEE 802.15.4   0x1672  0x0000  0x1672  0x0000                      118         Data Request
53  12:43:06,034428 0x12af  IEEE 802.15.4   0x0000  0x1672                              118         Ack
54  12:43:07,039823 0x12af  IEEE 802.15.4   0x1672  0x0000  0x1672  0x0000                      119         Data Request
55  12:43:07,040591 0x12af  IEEE 802.15.4   0x0000  0x1672                              119         Ack
56  12:43:07,560843 0x12af  ZigBee ZDP  0x1672  0x0000  0x1672  0x0000  0x0000      88  20  133 120 0   0   Node Descriptor Request, Nwk Addr: 0x0000
57  12:43:07,562763 0x12af  IEEE 802.15.4   0x0000  0x1672                              120         Ack
58  12:43:08,048328 0x12af  IEEE 802.15.4   0x1672  0x0000  0x1672  0x0000                      121         Data Request
59  12:43:08,049096 0x12af  IEEE 802.15.4   0x0000  0x1672                              121         Ack
60  12:43:08,061559 0x12af  ZigBee  0x0000  0x1672  0x0000  0x1672  0x1672      204 20      43  0   0   APS: Ack, Dst Endpt: 0, Src Endpt: 0
61  12:43:08,063383 0x12af  IEEE 802.15.4   0x1672  0x0000                              43          Ack
62  12:43:09,053362 0x12af  IEEE 802.15.4   0x1672  0x0000  0x1672  0x0000                      122         Data Request
63  12:43:09,054129 0x12af  IEEE 802.15.4   0x0000  0x1672                              122         Ack
64  12:43:09,065902 0x12af  ZigBee ZDP  0x0000  0x1672  0x0000  0x1672  0x1672      205 122 133 44  0   0   Node Descriptor Response, Rev: 22, Nwk Addr: 0x0000, Status: Success

It updating the TC-Link key OK and the system is staring configuring the device. But its going in sleep then its one sleeper.

Like one bind request is being replayed with one bind response but the coordinator and the coordinator is sending one ASP Ack but the device is sleeping and is not getting any 154 ack = the 802.15.4 layer is down then the device is sleeping.

No. Time    PAN Protocol    IEEE Src    IEEE Dst    Zigbee Src  Zigbee Dst  ZBN Dst Group Nr    ZBN Seq ZBA Seq ZDP Seq Nwk Seq Src EP  Dst EP  Info
196 12:43:28,243836 0x12af  ZigBee ZDP  0x1672  0x0000  0x1672  0x0000  0x0000      117 30  3   163 0   0   Bind Response, Status: Success
197 12:43:28,245724 0x12af  IEEE 802.15.4   0x0000  0x1672                              163         Ack
198 12:43:28,274492 0x12af  ZigBee  0x0000  0x1672  0x0000  0x1672  0x1672      233 30      65  0   0   APS: Ack, Dst Endpt: 0, Src Endpt: 0
199 12:43:28,279034 0x12af  ZigBee  0x0000  0x1672  0x0000  0x1672  0x1672      233 30      65  0   0   APS: Ack, Dst Endpt: 0, Src Endpt: 0
200 12:43:28,284211 0x12af  ZigBee  0x0000  0x1672  0x0000  0x1672  0x1672      233 30      65  0   0   APS: Ack, Dst Endpt: 0, Src Endpt: 0
201 12:43:28,287165 0x12af  ZigBee  0x0000  0x1672  0x0000  0x1672  0x1672      233 30      65  0   0   APS: Ack, Dst Endpt: 0, Src Endpt: 0
202 12:43:28,301623 0x12af  ZigBee  0x0000  0x1672  0x0000  0x1672  0x1672      233 30      66  0   0   APS: Ack, Dst Endpt: 0, Src Endpt: 0
203 12:43:28,305844 0x12af  ZigBee  0x0000  0x1672  0x0000  0x1672  0x1672      233 30      66  0   0   APS: Ack, Dst Endpt: 0, Src Endpt: 0
204 12:43:28,310702 0x12af  ZigBee  0x0000  0x1672  0x0000  0x1672  0x1672      233 30      66  0   0   APS: Ack, Dst Endpt: 0, Src Endpt: 0
205 12:43:28,313957 0x12af  ZigBee  0x0000  0x1672  0x0000  0x1672  0x1672      233 30      66  0   0   APS: Ack, Dst Endpt: 0, Src Endpt: 0
206 12:43:28,329054 0x12af  ZigBee  0x0000  0x1672  0x0000  0x1672  0x1672      233 30      67  0   0   APS: Ack, Dst Endpt: 0, Src Endpt: 0
207 12:43:28,334236 0x12af  ZigBee  0x0000  0x1672  0x0000  0x1672  0x1672      233 30      67  0   0   APS: Ack, Dst Endpt: 0, Src Endpt: 0
208 12:43:28,338452 0x12af  ZigBee  0x0000  0x1672  0x0000  0x1672  0x1672      233 30      67  0   0   APS: Ack, Dst Endpt: 0, Src Endpt: 0
209 12:43:28,346953 0x12af  ZigBee  0x0000  0x1672  0x0000  0x1672  0x1672      233 30      67  0   0   APS: Ack, Dst Endpt: 0, Src Endpt: 0

All sending from the coordinator have problems after the first sleeping and it can being that the coordinator have not setting up the End Device Timeout Request or its bugs in the firmware (in the device and / or the coordinator).

Try paring the sleeper to one good working Zigbee 3 router (that support end device timeout) and see if its working also using one stable TI firmware in the coordinator that have working end device time out implanted.

PS: No need posting the network key then having one working paring in the sniff and getting it then sending it to the joiner.

MattWestb commented 1 year ago

The end device request sent to the coordinator looks OK:

Frame 33: 56 bytes on wire (448 bits), 56 bytes captured (448 bits) on interface -, id 0
IEEE 802.15.4 Data, Dst: 0x0000, Src: 0x1672
ZigBee Network Layer Command, Dst: 0x0000, Src: 0x1672
    Frame Control Field: 0x1a09, Frame Type: Command, Discover Route: Suppress, Security, Destination, Extended Source Command
        .... .... .... ..01 = Frame Type: Command (0x1)
        .... .... ..00 10.. = Protocol Version: 2
        .... .... 00.. .... = Discover Route: Suppress (0x0)
        .... ...0 .... .... = Multicast: False
        .... ..1. .... .... = Security: True
        .... .0.. .... .... = Source Route: False
        .... 1... .... .... = Destination: True
        ...1 .... .... .... = Extended Source: True
        ..0. .... .... .... = End Device Initiator: False
    Destination: 0x0000
    Source: 0x1672
    Radius: 1
    Sequence Number: 86
    Destination: TexasIns_00:24:c1:69:02 (00:12:4b:00:24:c1:69:02)
    Extended Source: IEEERegi_ff:fe:d1:2d:e6 (3c:6a:2c:ff:fe:d1:2d:e6)
    ZigBee Security Header
        Security Control Field: 0x28, Key Id: Network Key, Extended Nonce
            ...0 1... = Key Id: Network Key (0x1)
            ..1. .... = Extended Nonce: True
        Frame Counter: 4097
        Extended Source: IEEERegi_ff:fe:d1:2d:e6 (3c:6a:2c:ff:fe:d1:2d:e6)
        Key Sequence Number: 0
        Message Integrity Code: 155825d6
        [Key: 846624840d2c90ee601725a232976a10]
        [Key Origin: 29]
    Command Frame: End Device Timeout Request
        Command Identifier: End Device Timeout Request (0x0b)
        Requested Timeout Enumeration: 256 min (8)
        End Device Configuration: 0x00

But i have not looking if every bit set OK but can comparing with one working joining of one real Zigbee 3 sleeper joining.

pipiche38 commented 1 year ago

@MattWestb thanks very much for the such deep investigation. I'm learning it here.

I'm using the standard @koenkk firmware from February 19th. on a SonOff key. What is sure is that I do not get this error on a Elelabs/Silicon based chipset.

I'll try your suggestion on pairing it via a router (and not the coordinator). Will come back

pipiche38 commented 1 year ago

Did a test with the latest firmware from (development) 20220928 and it is same or worst as this come more quickly

Has you mentioned it looks like the coordinator is doing as for a Receive on Idle (True) device. Which is not the case of that device.

CMS323 - Pairing + failure with zzh firmware 20220928pcapng.pcapng.zip

I also wonder why zigpy is doing retry at such speed ?

2022-10-23 12:02:29,876 DEBUG   :Received command: ZDO.MgmtBindRsp.Callback(Src=0x4FE6, Status=<Status.SUCCESS: 0>, BindTableEntries=3, StartIndex=0, BindTableList=[Binding(SrcAddress=3c:6a:2c:ff:fe:d1:2d:e6, SrcEndpoint=1, ClusterId=1, DstAddress=MultiAddress(addrmode=3, ieee=14:b4:57:ff:fe:36:3c:bb, endpoint=1)), Binding(SrcAddress=3c:6a:2c:ff:fe:d1:2d:e6, SrcEndpoint=2, ClusterId=1, DstAddress=MultiAddress(addrmode=3, ieee=14:b4:57:ff:fe:36:3c:bb, endpoint=1)), Binding(SrcAddress=3c:6a:2c:ff:fe:d1:2d:e6, SrcEndpoint=2, ClusterId=1026, DstAddress=MultiAddress(addrmode=3, ieee=14:b4:57:ff:fe:36:3c:bb, endpoint=1))])
2022-10-23 12:02:29,881 DEBUG   :Command was not handled
2022-10-23 12:02:29,885 DEBUG   :Received command: ZDO.MsgCbIncoming.Callback(Src=0x4FE6, IsBroadcast=<Bool.false: 0>, ClusterId=32819, SecurityUse=0, TSN=8, MacDst=0x0000, Data=b'\x00\x03\x00\x03\xE6\x2D\xD1\xFE\xFF\x2C\x6A\x3C\x01\x01\x00\x03\xBB\x3C\x36\xFE\xFF\x57\xB4\x14\x01\xE6\x2D\xD1\xFE\xFF\x2C\x6A\x3C\x02\x01\x00\x03\xBB\x3C\x36\xFE\xFF\x57\xB4\x14\x01\xE6\x2D\xD1\xFE\xFF\x2C\x6A\x3C\x02\x02\x04\x03\xBB\x3C\x36\xFE\xFF\x57\xB4\x14\x01')
2022-10-23 12:02:29,901 DEBUG   : [ ZigpyCom_4 29616] handle_message Sender: 4fe6 frame for plugin: 01800200a2ff00000080330000024fe60200000800030003e62dd1feff2c6a3c01010003bb3c36feff57b41401e62dd1feff2c6a3c02010003bb3c36feff57b41401e62dd1feff2c6a3c02020403bb3c36feff57b414018a03
2022-10-23 12:02:30,219 DEBUG   :Received command: AF.DataConfirm.Callback(Status=<Status.MAC_TRANSACTION_EXPIRED: 240>, Endpoint=1, TSN=3)
2022-10-23 12:02:30,224 DEBUG   :Sending request: UTIL.AssocGetWithAddress.Req(IEEE=3c:6a:2c:ff:fe:d1:2d:e6, NWK=0x0000)
2022-10-23 12:02:30,249 DEBUG   :Received command: UTIL.AssocGetWithAddress.Rsp(Device=Device(shortAddr=0x4FE6, addrIdx=4, nodeRelation=<NodeRelation.CHILD_RFD: 1>, devStatus=8, assocCnt=0, age=0, linkInfo=LinkInfo(txCounter=0, txCost=1, rxLqi=141, inKeySeqNum=0, inFrmCntr=0, txFailure=57187), endDev=AgingEndDevice(endDevCfg=32, deviceTimeout=268615739), timeoutCounter=0, keepaliveRcv=19, ctrl=197))
2022-10-23 12:02:30,254 DEBUG   :Sending request: UTIL.AssocRemove.Req(IEEE=3c:6a:2c:ff:fe:d1:2d:e6)
2022-10-23 12:02:30,265 DEBUG   :Received command: UTIL.AssocRemove.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-23 12:02:30,270 DEBUG   :Sending request: ZDO.ExtRouteDisc.Req(Dst=0x4FE6, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2022-10-23 12:02:30,281 DEBUG   :Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-23 12:02:31,585 DEBUG   :Request failed (Unsuccessful request status code: <Status.MAC_TRANSACTION_EXPIRED: 240>), retry attempt 2 of 5
2022-10-23 12:02:32,091 DEBUG   :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x4FE6), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=1, TSN=3, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x10\x03\x06\x00\x21\x00\x20\x10\x0E\xC0\xA8\x01')
2022-10-23 12:02:32,117 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-23 12:02:36,206 DEBUG   :Received command: AF.DataConfirm.Callback(Status=<Status.APS_NO_ACK: 183>, Endpoint=1, TSN=3)
2022-10-23 12:02:36,209 DEBUG   :Request failed (Unsuccessful request status code: <Status.APS_NO_ACK: 183>), retry attempt 3 of 5
2022-10-23 12:02:36,715 DEBUG   :Sending request: AF.DataRequestSrcRtg.Req(DstAddr=0x4FE6, DstEndpoint=1, SrcEndpoint=1, ClusterId=1, TSN=3, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, SourceRoute=[], Data=b'\x10\x03\x06\x00\x21\x00\x20\x10\x0E\xC0\xA8\x01')
2022-10-23 12:02:36,741 DEBUG   :Received command: AF.DataRequestSrcRtg.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-23 12:02:36,832 DEBUG   :Received command: AF.DataConfirm.Callback(Status=<Status.NWK_NO_ROUTE: 205>, Endpoint=1, TSN=3)
2022-10-23 12:02:36,838 DEBUG   :Sending request: ZDO.ExtRouteDisc.Req(Dst=0x4FE6, Options=<RouteDiscoveryOptions.UNICAST: 0>, Radius=30)
2022-10-23 12:02:36,848 DEBUG   :Received command: ZDO.ExtRouteDisc.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-23 12:02:38,151 DEBUG   :Request failed (Unsuccessful request status code: <Status.NWK_NO_ROUTE: 205>), retry attempt 4 of 5
2022-10-23 12:02:38,588 DEBUG   :Sending request: SYS.Ping.Req()
2022-10-23 12:02:38,597 DEBUG   :Received command: SYS.Ping.Rsp(Capabilities=<MTCapabilities.APP_CNF|GP|UTIL|ZDO|AF|SYS: 1625>)
2022-10-23 12:02:38,658 DEBUG   :Sending request: AF.DataRequestExt.Req(DstAddrModeAddress=AddrModeAddress(mode=<AddrMode.NWK: 2>, address=0x4FE6), DstEndpoint=1, DstPanId=0x0000, SrcEndpoint=1, ClusterId=1, TSN=3, Options=<TransmitOptions.SUPPRESS_ROUTE_DISC_NETWORK|ACK_REQUEST: 48>, Radius=30, Data=b'\x10\x03\x06\x00\x21\x00\x20\x10\x0E\xC0\xA8\x01')
2022-10-23 12:02:38,684 DEBUG   :Received command: AF.DataRequestExt.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-23 12:02:39,974 DEBUG   :Received command: AF.DataConfirm.Callback(Status=<Status.NWK_NO_ROUTE: 205>, Endpoint=1, TSN=3)
2022-10-23 12:02:39,978 DEBUG   :Request failed (Unsuccessful request status code: <Status.NWK_NO_ROUTE: 205>), retry attempt 5 of 5
2022-10-23 12:02:40,483 DEBUG   :Sending request: UTIL.AssocAdd.Req(NWK=0x4FE6, IEEE=3c:6a:2c:ff:fe:d1:2d:e6, NodeRelation=<NodeRelation.CHILD_RFD: 1>)
2022-10-23 12:02:40,494 DEBUG   :Received command: UTIL.AssocAdd.Rsp(Status=<Status.SUCCESS: 0>)
2022-10-23 12:02:40,518 INFO    : [ ZigpyCom_4 29616] process_raw_command - DeliveryError : Request failed after 5 attempts: <Status.NWK_NO_ROUTE: 205>
pipiche38 commented 1 year ago

Here is a smooth pairing with the elelabs

CMS323 - Pairing + fsmooth with elelabs.pcapng.zip

MattWestb commented 1 year ago

I analyzing some Z2M sniffs with TI firmware then having Zigbee 3 problems and the device was joining OK and doing all Zigbee 3 things OK also it was getting "end device timeout response" from the coordinator. You can looking in it if you like. zzh.zip The different is Silabs chips in both ends.

I was curious and looking for the chip vendor for the joinee 3c:6a:2c:ff:fe:d1:2d:e6 and its little strange if using online tools: https://macaddress.io/mac-address-lookup/mKRr0yaa5o.

So we is not knowing the Zigbee stack the device is running.

Edit: I taking on fast look on your new sniff !!

MattWestb commented 1 year ago

I have problems understanding the CMS323 - Pairing + failure with zzh firmware 20220928pcapng.pcapng.zip


Frame 75: 45 bytes on wire (360 bits), 45 bytes captured (360 bits) on interface -, id 0
IEEE 802.15.4 Data, Dst: 0x4fe6, Src: 0x0000
    Frame Control Field: 0x8861, Frame Type: Data, Acknowledge Request, PAN ID Compression, Destination Addressing Mode: Short/16-bit, Frame Version: IEEE Std 802.15.4-2003, Source Addressing Mode: Short/16-bit
    Sequence Number: 0
    Destination PAN: 0x0bbb
    Destination: 0x4fe6
    Source: 0x0000
    [Extended Source: SiliconL_ff:fe:36:3c:bb (14:b4:57:ff:fe:36:3c:bb)]
    [Origin: 22]
    [Ack In: 76]
    FCS: 0xb242 (Correct)
ZigBee Network Layer Data, Dst: 0x4fe6, Src: 0x0000
ZigBee Application Support Layer Ack, Dst Endpt: 0, Src Endpt: 0

The 802.15.4 layer (the radio network layer that Zigbee is building all on) is saying the coordinator is not one TI chip its one Silabs ?!?!?

In the CMS323 - Pairing + fsmooth with elelabs.pcapng.zip i have finding one strange frame form the device:

Frame 58: 62 bytes on wire (496 bits), 62 bytes captured (496 bits) on interface -, id 0
IEEE 802.15.4 Data, Dst: 0xea71, Src: 0x0000
    Frame Control Field: 0x8871, Frame Type: Data, Frame Pending, Acknowledge Request, PAN ID Compression, Destination Addressing Mode: Short/16-bit, Frame Version: IEEE Std 802.15.4-2003, Source Addressing Mode: Short/16-bit
        .... .... .... .001 = Frame Type: Data (0x1)
        .... .... .... 0... = Security Enabled: False
        .... .... ...1 .... = Frame Pending: True
        .... .... ..1. .... = Acknowledge Request: True
        .... .... .1.. .... = PAN ID Compression: True
        .... .... 0... .... = Reserved: False
        .... ...0 .... .... = Sequence Number Suppression: False
        .... ..0. .... .... = Information Elements Present: False
        .... 10.. .... .... = Destination Addressing Mode: Short/16-bit (0x2)
        ..00 .... .... .... = Frame Version: IEEE Std 802.15.4-2003 (0)
        10.. .... .... .... = Source Addressing Mode: Short/16-bit (0x2)
    Sequence Number: 99
    Destination PAN: 0x6e99
    Destination: 0xea71
    Source: 0x0000
    [Extended Source: SiliconL_ff:fe:a5:f3:07 (cc:cc:cc:ff:fe:a5:f3:07)]
    [Origin: 1]
    [Ack In: 59]
    FCS: 0xbeac (Correct)
ZigBee Network Layer Data, Dst: 0xea71, Src: 0x0000
    Frame Control Field: 0x0248, Frame Type: Data, Discover Route: Enable, Security Data
        .... .... .... ..00 = Frame Type: Data (0x0)
        .... .... ..00 10.. = Protocol Version: 2
        .... .... 01.. .... = Discover Route: Enable (0x1)
        .... ...0 .... .... = Multicast: False
        .... ..1. .... .... = Security: True
        .... .0.. .... .... = Source Route: False
        .... 0... .... .... = Destination: False
        ...0 .... .... .... = Extended Source: False
        ..0. .... .... .... = End Device Initiator: False
    Destination: 0xea71
    Source: 0x0000
    Radius: 30
    Sequence Number: 11
    [Extended Source: SiliconL_ff:fe:a5:f3:07 (cc:cc:cc:ff:fe:a5:f3:07)]
    [Origin: 1]
    ZigBee Security Header
ZigBee Application Support Layer Data, Dst Endpt: 0, Src Endpt: 0
    Frame Control Field: Data (0x40)
        .... ..00 = Frame Type: Data (0x0)
        .... 00.. = Delivery Mode: Unicast (0x0)
        ..0. .... = Security: False
        .1.. .... = Acknowledgement Request: True
        0... .... = Extended Header: False
    Destination Endpoint: 0
    Node Descriptor Response (Cluster ID: 0x8002)
    Profile: ZigBee Device Profile (0x0000)
    Source Endpoint: 0
    Counter: 193
ZigBee Device Profile, Node Descriptor Response, Rev: 71, Nwk Addr: 0x0000, Status: Success
    Sequence Number: 130
    Status: Success (0)
    Nwk Addr of Interest: 0x0000
    Node Descriptor
        .... .... .... .000 = Type: 0 (Coordinator)
        .... .... .... 0... = Complex Descriptor: False
        .... .... ...0 .... = User Descriptor: False
        .... 0... .... .... = 868MHz BPSK Band: False
        ..0. .... .... .... = 902MHz BPSK Band: False
        .0.. .... .... .... = 2.4GHz OQPSK Band: False
        0... .... .... .... = EU Sub-GHz FSK Band: False
        Capability Information: 0x80
            .... ...0 = Alternate Coordinator: False
            .... ..0. = Full-Function Device: False
            .... .0.. = AC Power: False
            .... 0... = Rx On When Idle: False
            .0.. .... = Security Capability: False
            1... .... = Allocate Short Address: True
        Manufacturer Code: 0x8000
        Max Buffer Size: 0
        Max Incoming Transfer Size: 11329
        Server Flags: 0x8f00
            .... .... .... ...0 = Primary Trust Center: False
            .... .... .... ..0. = Backup Trust Center: False
            .... .... .... .0.. = Primary Binding Table Cache: False
            .... .... .... 0... = Backup Binding Table Cache: False
            .... .... ...0 .... = Primary Discovery Cache: False
            .... .... ..0. .... = Backup Discovery Cache: False
            .... .... .0.. .... = Network Manager: False
            1000 111. .... .... = Stack Compliance Revision: 71
        Max Outgoing Transfer Size: 82
        Descriptor Capability Field: 0x40
            .... ...0 = Extended Active Endpoint List Available: False
            .... ..0. = Extended Simple Descriptor List Available: False

First is have not 2.4 GHz supported in the radio .0.. .... .... .... = 2.4GHz OQPSK Band: False and the Zigbee stack is not released yet (we is waiting for Zigbee R23 and new devices is running R22) 1000 111. .... .... = Stack Compliance Revision: 71.

The problem is that the "bad" sniffs is the coordinator is responding with one "normal" frame as posted in the first long analyze. Its also some bad formatted packed that is being corrupted but it shall not being any problem then the under layer (802.15.4) shall reseeding it or not acking it and the device shall reseeding it. It can also being that sniffing device have missing one or more package it possible checking but then must looking in every 154 frame and the acks that the counter is OK but its too much for the moment.

The rest of the paring looks OK and the device is working = great.

Can you redoing the sniff with the elelabs so can see if getting the same strange frame ? Also witch EZSP version is the elelabs running EZSP 6.10.3.0 ?

pipiche38 commented 1 year ago

I investigate on the IEEE confusion and as I'm doing those tests on my labs, the zzh was restored with a backup from elelabs. And so the restore overwrite the secondary IEEE of the CC2652R

:EZSP Radio manufacturer: Elelabs :EZSP Radio board name: ELR023 :EmberZNet version: 6.10.3.0 build 297

CMS323 - successfull-pairing-elelabs-ezsp.pcapng.zip

ZNP Radio manufacturer: Texas Instruments ZNP Radio board model: CC1352/CC2652, Z-Stack 3.30+ (build 20220928) ZNP Radio version: 3.3

CMS323 - failed pairing with zzh firmware 20220928.pcapng.zip

MattWestb commented 1 year ago

Elelabs have the same strange node description:

Frame 77: 62 bytes on wire (496 bits), 62 bytes captured (496 bits) on interface -, id 0
IEEE 802.15.4 Data, Dst: 0xbc44, Src: 0x0000
ZigBee Network Layer Data, Dst: 0xbc44, Src: 0x0000
ZigBee Application Support Layer Data, Dst Endpt: 0, Src Endpt: 0
ZigBee Device Profile, Node Descriptor Response, Rev: 71, Nwk Addr: 0x0000, Status: Success
    Sequence Number: 130
    Status: Success (0)
    Nwk Addr of Interest: 0x0000
    Node Descriptor
        .... .... .... .000 = Type: 0 (Coordinator)
        .... .... .... 0... = Complex Descriptor: False
        .... .... ...0 .... = User Descriptor: False
        .... 0... .... .... = 868MHz BPSK Band: False
        ..0. .... .... .... = 902MHz BPSK Band: False
        .0.. .... .... .... = 2.4GHz OQPSK Band: False
        0... .... .... .... = EU Sub-GHz FSK Band: False
        Capability Information: 0x80
        Manufacturer Code: 0x8000
        Max Buffer Size: 0
        Max Incoming Transfer Size: 11329
        Server Flags: 0x8f00
            .... .... .... ...0 = Primary Trust Center: False
            .... .... .... ..0. = Backup Trust Center: False
            .... .... .... .0.. = Primary Binding Table Cache: False
            .... .... .... 0... = Backup Binding Table Cache: False
            .... .... ...0 .... = Primary Discovery Cache: False
            .... .... ..0. .... = Backup Discovery Cache: False
            .... .... .0.. .... = Network Manager: False
            1000 111. .... .... = Stack Compliance Revision: 71
        Max Outgoing Transfer Size: 82
        Descriptor Capability Field: 0x40

but looks paring OK.

Edit: Then looking is the request done in sequence 61 and 62 and the response first time in 66 and 67 and looks OK and then its sending one more "version" with the strange information in 77 and 78 (the frame above). Is you overriding the manufacture ID then initiating the EZSP and is braking some other parameters (New Aqara devices need patched manufacture ID for working OK nad bellow can doing it but i dont knowing how its done in the code) ?

TI is sending one OK node description response:

Frame 154: 62 bytes on wire (496 bits), 62 bytes captured (496 bits) on interface -, id 0
IEEE 802.15.4 Data, Dst: 0x0000, Src: 0x8d9d
    Frame Control Field: 0x8861, Frame Type: Data, Acknowledge Request, PAN ID Compression, Destination Addressing Mode: Short/16-bit, Frame Version: IEEE Std 802.15.4-2003, Source Addressing Mode: Short/16-bit
        .... .... .... .001 = Frame Type: Data (0x1)
        .... .... .... 0... = Security Enabled: False
        .... .... ...0 .... = Frame Pending: False
        .... .... ..1. .... = Acknowledge Request: True
        .... .... .1.. .... = PAN ID Compression: True
        .... .... 0... .... = Reserved: False
        .... ...0 .... .... = Sequence Number Suppression: False
        .... ..0. .... .... = Information Elements Present: False
        .... 10.. .... .... = Destination Addressing Mode: Short/16-bit (0x2)
        ..00 .... .... .... = Frame Version: IEEE Std 802.15.4-2003 (0)
        10.. .... .... .... = Source Addressing Mode: Short/16-bit (0x2)
    Sequence Number: 100
    Destination PAN: 0xa8cd
    Destination: 0x0000
    Source: 0x8d9d
    [Extended Source: IEEERegi_ff:fe:d1:2d:e6 (3c:6a:2c:ff:fe:d1:2d:e6)]
    [Origin: 56]
    [Ack In: 155]
    FCS: 0x8c1e (Correct)
ZigBee Network Layer Data, Dst: 0x0000, Src: 0x8d9d
    Frame Control Field: 0x0208, Frame Type: Data, Discover Route: Suppress, Security Data
        .... .... .... ..00 = Frame Type: Data (0x0)
        .... .... ..00 10.. = Protocol Version: 2
        .... .... 00.. .... = Discover Route: Suppress (0x0)
        .... ...0 .... .... = Multicast: False
        .... ..1. .... .... = Security: True
        .... .0.. .... .... = Source Route: False
        .... 0... .... .... = Destination: False
        ...0 .... .... .... = Extended Source: False
        ..0. .... .... .... = End Device Initiator: False
    Destination: 0x0000
    Source: 0x8d9d
    Radius: 30
    Sequence Number: 119
    [Extended Source: IEEERegi_ff:fe:d1:2d:e6 (3c:6a:2c:ff:fe:d1:2d:e6)]
    [Origin: 56]
    ZigBee Security Header
ZigBee Application Support Layer Data, Dst Endpt: 0, Src Endpt: 0
    Frame Control Field: Data (0x40)
        .... ..00 = Frame Type: Data (0x0)
        .... 00.. = Delivery Mode: Unicast (0x0)
        ..0. .... = Security: False
        .1.. .... = Acknowledgement Request: True
        0... .... = Extended Header: False
    Destination Endpoint: 0
    Node Descriptor Response (Cluster ID: 0x8002)
    Profile: ZigBee Device Profile (0x0000)
    Source Endpoint: 0
    Counter: 203
ZigBee Device Profile, Node Descriptor Response, Rev: 22, Nwk Addr: 0x8d9d, Status: Success
    Sequence Number: 2
    Status: Success (0)
    Nwk Addr of Interest: 0x8d9d
    Node Descriptor
        .... .... .... .010 = Type: 2 (End Device)
        .... .... .... 0... = Complex Descriptor: False
        .... .... ...0 .... = User Descriptor: False
        .... 0... .... .... = 868MHz BPSK Band: False
        ..0. .... .... .... = 902MHz BPSK Band: False
        .1.. .... .... .... = 2.4GHz OQPSK Band: True
        0... .... .... .... = EU Sub-GHz FSK Band: False
        Capability Information: 0x80
            .... ...0 = Alternate Coordinator: False
            .... ..0. = Full-Function Device: False
            .... .0.. = AC Power: False
            .... 0... = Rx On When Idle: False
            .0.. .... = Security Capability: False
            1... .... = Allocate Short Address: True
        Manufacturer Code: 0x113c
        Max Buffer Size: 82
        Max Incoming Transfer Size: 82
        Server Flags: 0x2c00
            .... .... .... ...0 = Primary Trust Center: False
            .... .... .... ..0. = Backup Trust Center: False
            .... .... .... .0.. = Primary Binding Table Cache: False
            .... .... .... 0... = Backup Binding Table Cache: False
            .... .... ...0 .... = Primary Discovery Cache: False
            .... .... ..0. .... = Backup Discovery Cache: False
            .... .... .0.. .... = Network Manager: False
            0010 110. .... .... = Stack Compliance Revision: 22
        Max Outgoing Transfer Size: 82
        Descriptor Capability Field: 0x00
            .... ...0 = Extended Active Endpoint List Available: False
            .... ..0. = Extended Simple Descriptor List Available: False

End device timeout request is sent in frame 58 and acke in 154 in 59 and repeated in 60 and ackd in 61 so the device is doing all OK but no response from the coordinator that have revived the frame (acked in 154) = wrong.

One thinking then Elelabs EZSP 6.10.3.0 is using hashed TC-Link key so its no TC-Link keys in the key table on the chip (its calculated from the device IEEEE for all devices in the system) so i think its not good restoring one backup from it to one TI chip that is not "understanding" hashed TC-Link keys.

Can you doing one resettle of the TI coordinator (destroying the network and forming one new without restoring one old backup) and trying paring the device agen ?

Also interesting if you can trying joining one other Zigbee 3 sleeping end device device with the IT coordinator and see how its working (all updated IKEA controller is normally doing all right).

MattWestb commented 1 year ago

Bay the way now i see one TI chip in the ZZH coordinator; [Extended Source: TexasIns_00:23:8d:ab:93 (00:12:4b:00:23:8d:ab:93)]

zigbeefordomoticz commented 1 year ago

The 2 sniffs have been done on a fresh erase nvram. Then I form a new network, so should not have remaining data from a previous restore.

I have the same issue on a sonoff key

MattWestb commented 1 year ago

I dont have any TI coordinators (face i have 2 CC-2531 but they is not forming one real Zibbee network) but can you trying joining one other Zigbee 3 sleeper to the same TI stick ?

If that is working then its device firmware problem and if its not working then coordinator firmware / settings problems.

MattWestb commented 1 year ago

OK now i understand the Silabs IEEE was restored on the TI and making all looks was Silabs EZSP coordinator :-)))

pipiche38 commented 1 year ago

I dont have any TI coordinators (face i have 2 CC-2531 but they is not forming one real Zibbee network) but can you trying joining one other Zigbee 3 sleeper to the same TI stick ?

If that is working then its device firmware problem and if its not working then coordinator firmware / settings problems.

The only question, I would have is why it is happening with the TI coordinator and not a Silicon Labs one.

MattWestb commented 1 year ago

I cant saying what is going wrong but have asking for some more testing for pointing out the failing device.

I have looking one more time in the sniff i was posted from one Z2M user and is running one TI coordinator and is joining one zigbee 3 sleeper to one router (Silabs chip) and the device is requesting end device time out and the router is responding success.

The end device timeout is one zigbee 3 function in routers and the coordinator one router with one onboard trust center and no more or less. Also need to k owing if the end device time out response is doing the problems.

For saying its is the joining device or the TI coordinator the test must being done.

Without that i cant saying any thing if is TI coordinator or the strange sleeping end device or the settings in the TI coordinator.

In the sniff i posted is made from one TI coordinator that is joining one sleeper OK but its made thru one Silabs router so Z2M is TI coordinator trustcenter working OK but we is not knowing if the router part is working OK and is doing the problems or its the device that is not liking TI hardware.

@puddly can you doing one fast test paring one IKEA remote (or some other Zigbee 3 sleepers) with one TI coordinator and looking if the coordinator (the router part of the coordinator) is doing the end device time request OK ?

puddly commented 1 year ago

@MattWestb You're completely correct, this explains why IKEA dimmers are so difficult to join to my test network!

This looks like a bug in TI's Z-Stack? This portion of the stack doesn't appear to be open source source-available.

MattWestb commented 1 year ago

Thanks @puddly !!!

Ar you taking it to Z2M firmware cooker so they is aware of it and can looking if TI is fixing it ?

So in the end for building one good Zigbee system first some good routers and then end device joining them.

The funny thing its that the problem is not in the coordinator part is in the router part of the firmware.

@pipiche38 Can you try adding one good router device and then adding the device thru the router and see if its working OK ? In the sniff i having it was working OK and puddly have doing the same but need knowing if the device is liking it or not or the device have more strange problems.

pipiche38 commented 1 year ago

I'll try to work on that this evening. That is good if we are finding something. I have also @badzz whom is having trouble to pair a Lidl PIR

MattWestb commented 1 year ago

Great @pipiche38 !!

My experience is the old (square) LIDL PIR little tricky getting paired with ZHA but then its in its working OK and reporting IAS Zone OK. I have not sniffing what is doing the problem but i can doing it if needed after we have getting this strange device solved.

I using my "IKEA Billy EZSP" and is having most good routers in My production and test networks.

@badzz Can you doing one sniff then pairing the LIDL PIR and we can taking one look if its network related / coordinator or its only one stupid tuya device ?

pipiche38 commented 1 year ago

Happy to share a bad-pairing through the zzh coordinator and a smooth pairing when opening the network on a Frient Plug. Pairing through the router make the all process smooth and successfull!

Archive.zip

I hope that it helps ...

[EDIT] The device I'm pairing is a CMS323 from CASA.IA (OWON OEM). That is a PIR with 3 end points and 2 IAS enrollments needed (for Ep 0x01 and Ep 0x04)

MattWestb commented 1 year ago

My LIDL PIR is one https://zigbee.blakadder.com/Lidl_HG06335.html with IEEE bc:33:ac:ff:fe:61:97:e0 and is one Silabs chip https://macaddress.io/mac-address-lookup/QNRP4AnxRA.

The sniff have IEEE 3c:6a:2c:ff:fe:d1:2d:e6 and is not allocated (as the original problem device in this issue) https://macaddress.io/mac-address-lookup/d95pjpadRp.

Is it the same design but the other version or is it the the other design (LIDL have selling 2 different deigned PIRs) ?

In the TI direct paring we is not getting response for the end device timeout request and is expected but the paring is looking OK and all the network parts is being done with success and the device is broadcasting one Permit Join Request with data 180 = all is don in the network and now its the system that shall doing the custom config of the device.

The config is getting problems after some time and its looks like the device is failing in sleep and is not receiving the commands sent to it.

The paring thru Develco router (00:15:bc:00:2f:00:cc:66) is also not responding to the end device timeout request (i think the device is not supporting it and is having one old Zigbee stack or buggy one / not full R22 compatible) but its looks like the device is happy with it and is doing the network setup OK and is ending it with ending one Permit Join Request with data 180. Its some reseeding but the config if the device looks being made OK but its very crowded and its looks the system is redoing many things more times but in the end its looks working OK.

Wold being interesting see it paring with one EZSP coordinator if its working better then its getting one OK end device timeout response !!

I think = not knowing, that is the same problem with the end device is going in sleep and the host system is getting problems then paring with TI coordinators. Perhaps it the same chip inside and the Chinese have not registration the IEEE and is running one very "exotic" Zigbee stack.

It can being that the Develco router is doing the pulling if its children better then the TI coordinator router part is doing and its working OK with the problem device.

If like doing one "EZSP sniff" im interesting looking how its working with one "real" Zigbee 3 coordinator / router.

pipiche38 commented 1 year ago

I'm sorry the 3c:6a:2c:ff:fe:d1:2d:e6 is related to an other CMS. Basically I have 2 CMS323. Here attached are pairing in an Elelabs/Silicon Labs coordinator based.

Archive-elelabs.zip

MattWestb commented 1 year ago

The first paring with Elelabs was not working so well but i think also the sniffer was bad placed.

The second look very normal only the coordinator is little busy and bot replaying then doing routing and device update in its tables but after that all is n1ce acked in 514 and Zigbee app layer.

I think you have one wrong data setting in the bellow then the device is requesting node description its replaying with one OK frame 405 and one strange 416 that we have looking on before. But is it working OK letting it so !!!

The router paring is with our friend Develco_00:2f:00:cc:66 (00:15:bc:00:2f:00:cc:66) also looks OK some frames is resent and some is corrupted but in the end all looks working OK (the sniffer cant "see" all 110% the same as the device if not using the same antenna / radio as the device so its normal).

The Develo is not responding to the end device timeout request but is doing all other things OK so my conclusion is EZSP direct paring = OK, EZSP paring thru Develco = OK so Deveclo is not one bad router but not 100% Zigbee 3 and its working.

Was the device working OK in both cases (i think yes) ?

So in the end TI coordinator have 2 problems (or more correct the router part of it) that is making all problem.

I dont knowing if the router part is having problem with more "exotic devices" but very likely we have not found them yet.

If it was one of my EZSP system i have blocking the coordinator having direct children and the problem was away after paring the first router (i normally doing that for not getting battery draining in remotes) .

Our @puddly If you have time can you double checking my "findings" so im not have getting all wrong ? Thanks in advance !!

pipiche38 commented 1 year ago

You are right the device was working well. Especially on the IAS side Motion and Tamper. Yes, you advice me to block direct children on bellows, but I don't think we can do the same on ZNP.

MattWestb commented 1 year ago

No i dont advising that but in some cases is better doing it (most ZHA users like have 64 direct children on the coordinator but its only making problem if the host system or the coordinator (NCP on the SOC) is off line then the sleepers is getting problems and leaving or jumping in the network) for getting the mesh network working better or working around some problems like jumping end devices.

In (Z)HA i use CONFIG_MAX_END_DEVICE_CHILDREN: 0 after adding one or more routers and then restarting HA and end device cant using the coordinator as parent but working great on other routers.

I have asking puddly if TI is having the same function / command / config but i think it they is not having it.

pipiche38 commented 1 year ago

Not sure I understand what are the next steps ? Do we have to bring that issue to the attention of @koenkk ? Do we have just to leave with it.

MattWestb commented 1 year ago

I cant helping more then workaround if its possible i think only puddly can helping with that in Zigpy and firmware bugs i cant reporting then i have only licence for Silabs GSDK and no modern TI hardware.

I think it must being in interest of @koenkk then its making problems with many good behaving Zigbee 3 devices in all open systems that is using his firmware for TI chips.

pipiche38 commented 1 year ago

@MattWestb I just remove the Plugin and immediately everything went back to work.