When a new encrypted session is negotiated over CASE/PASE, we have to make sure, that the new negotiated session is brought to life before we send to the peer the last message on the CASE/PASE exchange (which is usually an "OK" SC status response to pase/case3).
The reason for this is: if we create ("unreserve", in the rs-matter code due to static allocations) the new session after the last status report is sent, the remote peer could be so fast, that it might send us messages for the new session before it is unreserved! (as we are async-awaiting).
This is exactly what happens in the message exchange below, and this mini-PR addresses this.
Excerpt (note the places which I've marked with "!!!!", these are the interesting ones):
I (100555) rs_matter::transport::core:
>>>>> UDP [fe80::1e:aecd:4055:22d5%2]:63143 [S,SID:0,CTR:3002959,SRC:3823d186c4aab990][I|A|R,EID:5632,PROTO:0,OP:32,ACTR:8bb2221]
SC::CASESigma3
=> Processing
I (101335) rs_matter::transport::exchange:
<<<<< UDP [fe80::1e:aecd:4055:22d5%2]:63143 [U,SID:0,CTR:8bb2223,DST:3823d186c4aab990][A|R,EID:5632,PROTO:0,OP:40,ACTR:3002959]
SC::StatusReport
=> Sending
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!! ^^^ HERE, the CASE negotiation is over - yet - the new session (SID:3) is still not active, as that happens further below!!!!
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
I (101355) rs_matter::transport::core:
>>>>> UDP [fe80::1e:aecd:4055:22d5%2]:63143 [S,SID:0,CTR:3002959,SRC:3823d186c4aab990][I|A|R,EID:5632,PROTO:0,OP:32,ACTR:8bb2221]
SC::CASESigma3
=> Duplicate, sending ACK
I (101365) rs_matter::transport::core:
<<<<< UDP [fe80::1e:aecd:4055:22d5%2]:63143 [U,SID:0,CTR:8bb2224,DST:3823d186c4aab990][A,EID:5632,PROTO:0,OP:10,ACTR:3002959]
SC::MRPStandAloneAck
=> Sending (system)
I (101405) rs_matter::transport::core:
>>>>> UDP [fe80::1e:aecd:4055:22d5%2]:63143 [S,SID:0,CTR:3002959,SRC:3823d186c4aab990][I|A|R,EID:5632,PROTO:0,OP:32,ACTR:8bb2221]
SC::CASESigma3
=> Duplicate, sending ACK
I (101415) rs_matter::transport::core:
<<<<< UDP [fe80::1e:aecd:4055:22d5%2]:63143 [U,SID:0,CTR:8bb2225,DST:3823d186c4aab990][A,EID:5632,PROTO:0,OP:10,ACTR:3002959]
SC::MRPStandAloneAck
=> Sending (system)
W (101445) rs_matter::transport::core:
>>>>> UDP [fe80::1e:aecd:4055:22d5%2]:63143 [SID:3,CTR:e74ea17][(encoded)]
=> No valid session found, dropping
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!! ^^^ Problem 1, see further below for an explanation
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
W (101465) rs_matter::transport::core:
>>>>> UDP [fe80::1e:aecd:4055:22d5%2]:63143 [SID:3,CTR:e74ea18][(encoded)]
=> No valid session found, dropping
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!! ^^^ Problem 2
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
W (101475) rs_matter::transport::core:
>>>>> UDP [fe80::1e:aecd:4055:22d5%2]:63143 [SID:3,CTR:e74ea19][(encoded)]
=> No valid session found, dropping
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!! ^^^ Problem 3
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
I (101495) rs_matter::transport::core:
>>>>> UDP [fe80::1e:aecd:4055:22d5%2]:63143 [S,SID:0,CTR:300295a,SRC:3823d186c4aab990][I|A,EID:5632,PROTO:0,OP:10,ACTR:8bb2223]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
^^^ FINALLY HERE, the new case session is active on our side - because we just received an ACK for our "successful case3 status response from above". But here it is too late - in the mean time, as per above - we had been bombarded with messages for SID:3, which we could not handle!!!!
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
I (101505) rs_matter::respond: Responder: Handler 0 / exchange 6::0: Completed
I (101595) rs_matter::transport::session: New exchange: 7::0 [SID:3,RSID:ccf9,EID:5636] :: Responder(AcceptPending)
I (101595) rs_matter::transport::core:
>>>>> UDP [fe80::1e:aecd:4055:22d5%2]:63143 [SID:3,CTR:e74ea1a][I|R,EID:5636,PROTO:1,OP:8]
IM::InvokeRequest
=> Processing (new exchange)
I (101615) rs_matter::transport::core: Exchange 7::0 [SID:3,RSID:ccf9,EID:5636]: Accepted
I (101615) rs_matter::respond: Responder: Handler 0 / exchange 7::0: Starting
I (101635) rs_matter::data_model::sdm::noc: Handling command Update Fabric Label
I (101635) rs_matter::transport::exchange:
<<<<< UDP [fe80::1e:aecd:4055:22d5%2]:63143 [SID:ccf9,CTR:ba2efb8][A|R,EID:5636,PROTO:1,OP:9,ACTR:e74ea1a]
IM::InvokeResponse
=> Sending
I (101675) rs_matter::transport::core:
>>>>> UDP [fe80::1e:aecd:4055:22d5%2]:63143 [SID:3,CTR:e74ea1b][I|A,EID:5636,PROTO:0,OP:10,ACTR:ba2efb8]
SC::MRPStandAloneAck
=> Standalone Ack, dropping
I (101685) rs_matter::respond: Responder: Handler 0 / exchange 7::0: Completed
I (101795) rs_matter::transport::core:
>>>>> UDP [fe80::1e:aecd:4055:22d5%2]:63143 [SID:3,CTR:e74ea19][I|R,EID:5635,PROTO:1,OP:2]
IM::ReadRequest
=> Duplicate, sending ACK
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!! ^^^ And only now, here we start to understand what our remote peer was sending us, but oh well, too late
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
I (101805) rs_matter::transport::core:
<<<<< UDP [fe80::1e:aecd:4055:22d5%2]:63143 [SID:ccf9,CTR:ba2efb9][A,EID:5635,PROTO:0,OP:10,ACTR:e74ea19]
SC::MRPStandAloneAck
=> Sending (system)
I (101835) rs_matter::transport::core:
>>>>> UDP [fe80::1e:aecd:4055:22d5%2]:63143 [SID:3,CTR:e74ea17][I|R,EID:5633,PROTO:1,OP:2]
IM::ReadRequest
=> Duplicate, sending ACK
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!! ^^^ And only now, here we start to understand what our remote peer was sending us, but oh well, too late
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
I (101845) rs_matter::transport::core:
<<<<< UDP [fe80::1e:aecd:4055:22d5%2]:63143 [SID:ccf9,CTR:ba2efba][A,EID:5633,PROTO:0,OP:10,ACTR:e74ea17]
SC::MRPStandAloneAck
=> Sending (system)
I (101875) rs_matter::transport::core:
>>>>> UDP [fe80::1e:aecd:4055:22d5%2]:63143 [SID:3,CTR:e74ea18][I|R,EID:5634,PROTO:1,OP:3]
IM::SubscribeRequest
=> Duplicate, sending ACK
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
!!!! ^^^ And only now, here we start to understand what our remote peer was sending us, but oh well, too late
!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!
I (101885) rs_matter::transport::core:
<<<<< UDP [fe80::1e:aecd:4055:22d5%2]:63143 [SID:ccf9,CTR:ba2efbb][A,EID:5634,PROTO:0,OP:10,ACTR:e74ea18]
SC::MRPStandAloneAck
=> Sending (system)
I (101995) light: Light toggled
I (107005) light: Light toggled
I (107935) rs_matter::transport::session: New exchange: 8::0 [SID:0,RSID:0,EID:5637] :: Responder(AcceptPending)
I (107935) rs_matter::transport::core:
When a new encrypted session is negotiated over CASE/PASE, we have to make sure, that the new negotiated session is brought to life before we send to the peer the last message on the CASE/PASE exchange (which is usually an "OK" SC status response to pase/case3).
The reason for this is: if we create ("unreserve", in the
rs-mattercode due to static allocations) the new session after the last status report is sent, the remote peer could be so fast, that it might send us messages for the new session before it is unreserved! (as we are async-awaiting).This is exactly what happens in the message exchange below, and this mini-PR addresses this.
Excerpt (note the places which I've marked with "!!!!", these are the interesting ones):