search

openthread / ot-commissioner

OpenThread Commissioner, a Thread commissioner for joining new Thread devices and managing Thread networks.
https://openthread.io/
BSD 3-Clause "New" or "Revised" License
49 stars 36 forks source link

Transmission of the Ack message to the border router via the transaction pattern query/Answer_con from the CoAP layer was unsuccessful. #282

Open ZhangLe2016 opened 3 months ago

ZhangLe2016 commented 3 months ago

In a functionality of commissioner , the MGMT_PANID_QUERY.qry and MGMT_PANID_CONFLICT.ans messages exchange determines whether a PAN ID is in use. The expected transaction process is outlined in diagram 1. However, the actual transaction process, shown in diagram 2, reveals that the border router retransmits the same MGMT_PANID_CONFLICT.ans message three times due to the lack of a successful acknowledgment (ACK) message from the commissioner.

Screenshot from 2024-05-27 16-04-37

reproduce method:

  1. start a border router
  2. start a ot-commissioner
> config set pskc 445f2b5ca6f2a93a55ce570a70efeecb
config set pskc 445f2b5ca6f2a93a55ce570a70efeecb
[done]

> start 192.168.9.2 49154
start 192.168.9.2 49154
[done]

> panid query 0xFFFF 0x1234 fda7:4266:2337:da23:0:ff:fe00:fc00 
panid query 0xFFFF 0x1234 fda7:4266:2337:da23:0:ff:fe00:fc00 
[done]
  1. check the syslog from the ot-commissioner
2024-05-27T07:33:41.293396+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ info  ] [ config ] Id = OT-Commissioner
2024-05-27T07:33:41.294187+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ info  ] [ config ] enable CCM = false
2024-05-27T07:33:41.294230+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ info  ] [ config ] domain name = Thread
2024-05-27T07:33:41.294264+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ info  ] [ config ] keep alive interval = 40
2024-05-27T07:33:41.294315+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ info  ] [ config ] enable DTLS debug logging = false
2024-05-27T07:33:41.294381+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ info  ] [ config ] maximum connection number = 100
2024-05-27T07:33:41.294419+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ info  ] [ meshcop ] event loop started in background thread
2024-05-27T07:33:48.428824+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ meshcop ] starting petition: border agent = (192.168.9.2, 49154)
2024-05-27T07:33:48.510994+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] Generated KEK
2024-05-27T07:33:48.524525+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ meshcop ] DTLS connection to border agent succeed
2024-05-27T07:33:48.524629+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully write data: len=35, 48020001020efec820521bcdb163026370ff0a0f4f542d436f6d6d697373696f6e6572
2024-05-27T07:33:48.524700+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ meshcop ] sent petition request
2024-05-27T07:33:48.524938+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully read data: len=4, 60000001
2024-05-27T07:33:48.614338+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully read data: len=37, 5844fe6c020efec820521bcdff1001010a0f4f542d436f6d6d697373696f6e65720b024eb8
2024-05-27T07:33:48.614461+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ info  ] [ meshcop ] petition succeed, start keep-alive timer with 40 seconds
2024-05-27T07:33:48.614511+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully write data: len=30, 48020002f8c0bcb1495a1636b163026167ff0d0a0e00350207050301040c
2024-05-27T07:33:48.614566+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ mgmt ] sent MGMT_ACTIVE_GET.req
2024-05-27T07:33:48.615400+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully read data: len=118, 68440002f8c0bcb1495a1636ff0e080000000000010000000300000f35060004001fffe0020811111111222222220708fda742662337da23051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f010212340410445f2b5ca6f2a93a55ce570a70efeecb0c0402a0f7f8
2024-05-27T07:33:48.615601+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully write data: len=21, 4802000394f4683e076316ebb163026167ff0d0107
2024-05-27T07:33:48.615655+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ mgmt ] sent MGMT_ACTIVE_GET.req
2024-05-27T07:33:48.615684+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ mgmt ] sent MGMT_PENDING_GET.req
2024-05-27T07:33:48.616157+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully read data: len=23, 6844000394f4683e076316ebff0708fda742662337da23
2024-05-27T07:33:48.616378+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully write data: len=76, 580200044f43e1b3dd9d00f1b163027574ff3110fda742662337da23000000fffe00fc0030ff0024a582f0bf4802000122fcce7a29f7c1fcb163027067ff0d0c0e00350207050301040c3433
2024-05-27T07:33:48.616795+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully read data: len=50, 5202fe6d1a60b163027572ff30ff0010f0bfa5826844000122fcce7a29f7c1fc3110fda742662337da23000000fffe00fc00
2024-05-27T07:33:48.617039+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully write data: len=70, 580200053181bbfb9c097840b163027574ff3110fda742662337da23000000fffe00fc0030ff001ea582f0bf48020002a0b9705cb3488c8fb163026373ff0b024eb8120203e8
2024-05-27T07:33:48.617087+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ mgmt ] sent MGMT_COMMISSIONER_SET.req
2024-05-27T07:33:48.686510+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully read data: len=54, 5202fe6eb186b163027572ff30ff0014f0bfa58268440002a0b9705cb3488c8fff1001013110fda742662337da23000000fffe00fc00
2024-05-27T07:33:48.686647+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully write data: len=72, 580200061cf2e96c617483e8b163027574ff3110fda742662337da23000000fffe00fc0030ff0020a582f0bf480200037785ac3f88656823b163026367ff0d080b09083d3e124142
2024-05-27T07:33:48.686697+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ mgmt ] sent MGMT_COMMISSIONER_GET.req
2024-05-27T07:33:48.687119+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully read data: len=63, 5202fe6f7de0b163027572ff30ff001df0bfa582684400037785ac3f88656823ff0b024eb80902b800120203e83110fda742662337da23000000fffe00fc00
2024-05-27T07:33:56.894696+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully write data: len=78, 580200078e5887173f90e7c7b163027574ff3110fda742662337da23000000fffe00fc0030ff0026a582f0bf480200047114e759f7bf875eb163027071ff0b024eb83506000407fff80001021234
2024-05-27T07:33:56.894857+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully read data: len=50, 5202fe7047a6b163027572ff30ff0010f0bfa582684400047114e759f7bf875e3110fda742662337da23000000fffe00fc00
2024-05-27T07:34:00.913170+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully read data: len=62, 5202fe71a393b163027572ff30ff001cf0bff0bf4202582af41fb163027063ff3506000400010000010212343110fda742662337da23000000fffe00b800
2024-05-27T07:34:00.913991+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ info  ] [ mgmt ] received MGMT_PANID_CONFLICT.ans from fda7:4266:2337:da23:0:ff:fe00:b800
2024-05-27T07:34:00.914052+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully write data: len=50, 58020008f189755fd195e9e4b163027574ff3110fda742662337da23000000fffe00b80030ff000aa582f0bf6244582af41f
2024-05-27T07:34:03.274230+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully read data: len=62, 5202fe723d39b163027572ff30ff001cf0bff0bf4202582af41fb163027063ff3506000400010000010212343110fda742662337da23000000fffe00b800
2024-05-27T07:34:03.274351+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ info  ] [ coap ] server(=0x5555558bc4a0) found cached CoAP response for resource /c/pc
2024-05-27T07:34:03.274422+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully write data: len=50, 5802000993c1df3377d0e367b163027574ff3110fda742662337da23000000fffe00b80030ff000aa582f0bf6244582af41f
2024-05-27T07:34:07.995773+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully read data: len=62, 5202fe739e89b163027572ff30ff001cf0bff0bf4202582af41fb163027063ff3506000400010000010212343110fda742662337da23000000fffe00b800
2024-05-27T07:34:07.996269+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ info  ] [ coap ] server(=0x5555558bc4a0) found cached CoAP response for resource /c/pc
2024-05-27T07:34:07.996330+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully write data: len=50, 5802000addab71801c354e9fb163027574ff3110fda742662337da23000000fffe00b80030ff000aa582f0bf6244582af41f
2024-05-27T07:34:17.439719+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully read data: len=62, 5202fe74dad9b163027572ff30ff001cf0bff0bf4202582af41fb163027063ff3506000400010000010212343110fda742662337da23000000fffe00b800
2024-05-27T07:34:17.440190+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ info  ] [ coap ] server(=0x5555558bc4a0) found cached CoAP response for resource /c/pc
2024-05-27T07:34:17.440253+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully write data: len=50, 5802000b88335277a05dfd60b163027574ff3110fda742662337da23000000fffe00b80030ff000aa582f0bf6244582af41f
2024-05-27T07:34:28.628199+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully write data: len=25, 4802000cad5015c497b5fbdab163026361ff1001010b024eb8
2024-05-27T07:34:28.628352+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ meshcop ] sent keep alive message: keepAlive=true
2024-05-27T07:34:28.628399+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully read data: len=4, 6000000c
2024-05-27T07:34:28.628485+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ debug ] [ dtls ] session(=0x5555558bb428) successfully read data: len=16, 5844fe75ad5015c497b5fbdaff100101
2024-05-27T07:34:28.628545+00:00 thread-lezhan.c.googlers.com ot-commissioner[4062975]: [ info  ] [ meshcop ] keep alive message accepted, keep-alive timer restarted
ZhangLe2016 commented 2 months ago

The RC is the source port of CoAP ACK is different with the dest port of CoAP Answer. Referring to the spec 10.9:

the *4 port could be a ephemeral value from the Thread device side, but it is required that the outgoing response from the commissioner side needs to use it as the dest port and MM: (61631) is used as the source port.

I think PR #279 could solve this issue.

image