Closed ivmarkov closed 1 month ago
Just found the dump showing the "mrp" issue (the first one) and why the fix is what it is. JFYI:
>>>>> UDP [fe80::8d7:cf23:8b0b:f715%2]:51398 [S,SID:0,CTR:a8ed77a,SRC:6584ffecdb8c6893][I|R,EID:6247,PROTO:0,OP:20]
SC::PBKDFParamRequest
=> Processing (new exchange)
I (13346) rs_matter::transport::core: Exchange 0::0 [SID:0,RSID:0,EID:6247]: Accepted
I (13346) rs_matter::respond: Responder: Handler 0 / exchange 0::0: Starting
I (13356) rs_matter::transport::exchange:
<<<<< UDP [fe80::8d7:cf23:8b0b:f715%2]:51398 [U,SID:0,CTR:75d6397,DST:6584ffecdb8c6893][A|R,EID:6247,PROTO:0,OP:21,ACTR:a8ed77a]
SC::PBKDFParamResponse
=> Sending
I (13576) rs_matter::transport::exchange:
<<<<< UDP [fe80::8d7:cf23:8b0b:f715%2]:51398 [U,SID:0,CTR:75d6397,DST:6584ffecdb8c6893][A|R,EID:6247,PROTO:0,OP:21,ACTR:a8ed77a]
SC::PBKDFParamResponse
=> Re-sending
I (13606) rs_matter::transport::core:
>>>>> UDP [fe80::8d7:cf23:8b0b:f715%2]:51398 [S,SID:0,CTR:a8ed77a,SRC:6584ffecdb8c6893][I|R,EID:6247,PROTO:0,OP:20]
SC::PBKDFParamRequest
=> Duplicate, sending ACK
I (13616) rs_matter::transport::core:
<<<<< UDP [fe80::8d7:cf23:8b0b:f715%2]:51398 [U,SID:0,CTR:75d6398,DST:6584ffecdb8c6893][A,EID:6247,PROTO:0,OP:10,ACTR:a8ed77a]
SC::MRPStandAloneAck
=> Sending (system)
I (13636) light_eth: Light toggled
I (13716) rs_matter::transport::core:
>>>>> UDP [fe80::8d7:cf23:8b0b:f715%2]:51398 [S,SID:0,CTR:a8ed77b,SRC:6584ffecdb8c6893][I|A|R,EID:6247,PROTO:0,OP:22,ACTR:75d6397]
SC::PASEPake1
=> Processing
I (16596) rs_matter::transport::exchange:
<<<<< UDP [fe80::8d7:cf23:8b0b:f715%2]:51398 [U,SID:0,CTR:75d6399,DST:6584ffecdb8c6893][A|R,EID:6247,PROTO:0,OP:23,ACTR:a8ed77b]
SC::PASEPake2
=> Sending
>>>> HERE >>>>: W (16616) rs_matter::transport::mrp: Mismatch in retrans-table's msg counter and received msg counter: received 75d6397, expected 75d6399.
I (16616) rs_matter::transport::core:
>>>>> UDP [fe80::8d7:cf23:8b0b:f715%2]:51398 [S,SID:0,CTR:a8ed77c,SRC:6584ffecdb8c6893][I|A,EID:6247,PROTO:0,OP:10,ACTR:75d6397]
SC::MRPStandAloneAck
=> Duplicate, sending ACK
The last ^^^ message is what causes the MRP "issue", and the reason is, the peer receives our second PBKDFParamResponse
very late.
By that time, the conversation has advanced to PASEPake1
of which we are awaiting an ACK.
As mentioned in #177, this is the follow-up PR that addresses the actual two bugs I found:
(1) In
mrp.rs
(our message ACK and re-transmission logic):error!
but not handled in any way. As a result, the logic was assuming that we got ACK for the ID we were waiting for and stopped re-transmitting the message, which is wrong!ErrorCode::Duplicate
because this message - in fact - is a duplicate. And then send an ACK if the message requires it.(2) in
core.rs
, functiondecode_packet
:Finally, the following additional logging adjustments:
mrp
"mismatch" logicMsgSyncCounter
request, due to the proto header not being decoded (as we don't have a session, and thus proto hdr default state was containing 0s for opcode and proto ID). This is now fixed.