Critical bug fix: Discarding packets fixed?

[philips77]

This PR fixes #300. It may be related to #439 and #228 or #218.

Issue

During reassembly packets of a single segmented message may be received in arbitrary order and should be accepted. It is possible to get higher SEQ before a lower one, due to a packet loss, for example.

For that reason long time ago in lower transport layer a check has been added:

IOS-nRF-Mesh-Library/nRFMeshProvision/Layers/Lower Transport Layer/LowerTransportLayer.swift

Lines 386 to 399 in 0070766

	// In general, the SeqAuth of the received message must be greater
	// than SeqAuth of any previously received message from the same source.
	// However, for SAR (Segmentation and Reassembly) sessions, it is
	// the SeqAuth of the message, not segment, that is being checked.
	// If SAR is active (at least one segment for the same SeqAuth has
	// been previously received), the segments may be processed in any order.
	// The SeqAuth of this message must be greater or equal to the last one.
	var reassemblyInProgress = false
	if networkPdu.isSegmented {
	let sequenceZero = UInt16(sequence & 0x1FFF)
	let key = UInt32(keyFor: networkPdu.source, sequenceZero: sequenceZero)
	reassemblyInProgress = incompleteSegments[key] != nil ||
	acknowledgments[networkPdu.source]?.sequenceZero == sequenceZero
	}

In case the reassemblyInProgress flag was set, the packet was not discarded if the SeqAuth of the segmented message (that is calculated using IV Index, SEQ of the received message and seqZero of the segment) was equal to the SeqAuth of currently reassembled message:

IOS-nRF-Mesh-Library/nRFMeshProvision/Layers/Lower Transport Layer/LowerTransportLayer.swift

Lines 418 to 423 in 0070766

	guard receivedSeqAuth > localSeqAuth || missed ||
	(reassemblyInProgress && receivedSeqAuth == localSeqAuth) else {
	// Ignore that message.
	logger?.w(.lowerTransport, "Discarding packet (seqAuth: \(receivedSeqAuth), expected > \(localSeqAuth))")
	return false
	}

However, as you know, life is not that easy. Have a look at the log:

// The phone sends a long segmented message, 6 segments
[...]
Sending Segmented Access Message (akf: 0, szmic: 0, seqZero: 1265, segO: 5, segN: 5, data: 0xE80319C061DF6208E9CEC642)
Sending Network PDU (ivi: 0, nid: 0x67, ctl: 0, ttl: 5, seq: 1278, src: 0F00, dst: 0003, transportPdu: 0x248D765F95144810777CB7853DE2988D, netMic: 0xAEB82C34) encrypted using Primary Network Key (index: 0)
-> 0x006736AD8F9884861291248D765F95144810777CB7853DE2988DAEB82C34

// The device sends ACKs while accepting segments. It repeats a lot of them.
<- 0x006713C79072734FE278AE417AB2D311CF72A4DD3EC7D87AA2
Network PDU (ivi: 0, nid: 0x67, ctl: 1, ttl: 6, seq: 14343, src: 0003, dst: 0F00, transportPdu: 0xAE417AB2D311CF, netMic: 0x72A4DD3EC7D87AA2) received
ACK (seqZero: 1265, ackedSegments: 0x0000000F) received (decrypted using key: Primary Network Key (index: 0))
<- 0x006780DA254AC16FC8FF1321DEF705CE1C34CED142CA8F4174
Network PDU (ivi: 0, nid: 0x67, ctl: 1, ttl: 6, seq: 14344, src: 0003, dst: 0F00, transportPdu: 0x1321DEF705CE1C, netMic: 0x34CED142CA8F4174) received
ACK (seqZero: 1265, ackedSegments: 0x0000001F) received (decrypted using key: Primary Network Key (index: 0))
<- 0x0067D93E61B982F7EB94FE0D9437C07800750E4C32CB6E6621
Network PDU (ivi: 0, nid: 0x67, ctl: 1, ttl: 6, seq: 14345, src: 0003, dst: 0F00, transportPdu: 0xFE0D9437C07800, netMic: 0x750E4C32CB6E6621) received
ACK (seqZero: 1265, ackedSegments: 0x0000001F) received (decrypted using key: Primary Network Key (index: 0))
<- 0x006741AAEE95FC371032957D09B990527025DE1CCC6C4EDE24
Network PDU (ivi: 0, nid: 0x67, ctl: 1, ttl: 6, seq: 14346, src: 0003, dst: 0F00, transportPdu: 0x957D09B9905270, netMic: 0x25DE1CCC6C4EDE24) received
ACK (seqZero: 1265, ackedSegments: 0x0000001F) received (decrypted using key: Primary Network Key (index: 0))
<- 0x00675E1C6C2B917BF51D4B9578678DE26A04CF2CBE7793B167
Network PDU (ivi: 0, nid: 0x67, ctl: 1, ttl: 6, seq: 14347, src: 0003, dst: 0F00, transportPdu: 0x4B9578678DE26A, netMic: 0x04CF2CBE7793B167) received
ACK (seqZero: 1265, ackedSegments: 0x0000003F) received (decrypted using key: Primary Network Key (index: 0))
<- 0x00678278895A3B0EAC7F51E6A3539E4EFCF0CC7EFAE1F7C8BF
Network PDU (ivi: 0, nid: 0x67, ctl: 1, ttl: 6, seq: 14348, src: 0003, dst: 0F00, transportPdu: 0x51E6A3539E4EFC, netMic: 0xF0CC7EFAE1F7C8BF) received
ACK (seqZero: 1265, ackedSegments: 0x0000003F) received (decrypted using key: Primary Network Key (index: 0))
<- 0x0067E84C590C93B26A72ED68C2410ED1FF03C54DE2E79D7664
Network PDU (ivi: 0, nid: 0x67, ctl: 1, ttl: 6, seq: 14349, src: 0003, dst: 0F00, transportPdu: 0xED68C2410ED1FF, netMic: 0x03C54DE2E79D7664) received
ACK (seqZero: 1265, ackedSegments: 0x0000003F) received (decrypted using key: Primary Network Key (index: 0))
<- 0x00672EA25D3195269CF1009DEBF57EF7EF6C2E451107AEB63A
Network PDU (ivi: 0, nid: 0x67, ctl: 1, ttl: 6, seq: 14350, src: 0003, dst: 0F00, transportPdu: 0x009DEBF57EF7EF, netMic: 0x6C2E451107AEB63A) received
ACK (seqZero: 1265, ackedSegments: 0x0000003F) received (decrypted using key: Primary Network Key (index: 0))

// A device sends a message, single-segment 
<- 0x0067EB82D288DC44A5465EB27D482AA82992B39298EC0B9A85
Network PDU (ivi: 0, nid: 0x67, ctl: 0, ttl: 6, seq: 14351, src: 0003, dst: 0F00, transportPdu: 0x5EB27D482AA82992B39298, netMic: 0xEC0B9A85) received
Segmented Access Message (akf: 0, szmic: 0, seqZero: 6159, segO: 0, segN: 0, data: 0xAE6608D4C71ADE) received (decrypted using key: Primary Network Key (index: 0))
Access Message (akf: 0, szmic: 0, data: 0xAE6608D4C71ADE) received
Upper Transport PDU (encrypted data: 0xAE6608, transMic: 0xD4C71ADE) received
Access PDU (opcode: 0x805E, parameters: 0x03) received (decrypted using key: My Device's Device Key)
RemoteProvisioningPDUOutboundReport(outboundPduNumber: 3, isSegmented: true) received from: 0003

// The phone replies with ACK
Sending ACK (seqZero: 6159, ackedSegments: 0x00000001)
Sending Network PDU (ivi: 0, nid: 0x67, ctl: 1, ttl: 5, seq: 1279, src: 0F00, dst: 0003, transportPdu: 0x7D7509BD44AE72, netMic: 0xD4F3CF631D7C1372) encrypted using Primary Network Key (index: 0)
-> 0x00674EA1BC5C6EEAF5117D7509BD44AE72D4F3CF631D7C1372

// But we're still getting the ACKs
<- 0x0067A0C45446EA8403587AA113AFF1A7F58116C1B142CBDF11
Network PDU (ivi: 0, nid: 0x67, ctl: 1, ttl: 6, seq: 14352, src: 0003, dst: 0F00, transportPdu: 0x7AA113AFF1A7F5, netMic: 0x8116C1B142CBDF11) received
ACK (seqZero: 1265, ackedSegments: 0x0000003F) received (decrypted using key: Primary Network Key (index: 0))
<- 0x0067E70F48EAF7E11F7157EB33E22174A0A366CF352F3BEEED
Network PDU (ivi: 0, nid: 0x67, ctl: 1, ttl: 6, seq: 14354, src: 0003, dst: 0F00, transportPdu: 0x57EB33E22174A0, netMic: 0xA366CF352F3BEEED) received
ACK (seqZero: 1265, ackedSegments: 0x0000003F) received (decrypted using key: Primary Network Key (index: 0))
<- 0x00672BF3949C595671D24C90DA9A24B76D8BB17490A1F92A3E
Network PDU (ivi: 0, nid: 0x67, ctl: 1, ttl: 6, seq: 14355, src: 0003, dst: 0F00, transportPdu: 0x4C90DA9A24B76D, netMic: 0x8BB17490A1F92A3E) received
ACK (seqZero: 1265, ackedSegments: 0x0000003F) received (decrypted using key: Primary Network Key (index: 0))
<- 0x006723704233091C2F01636E1E592CE148B90EC050304358D2
Network PDU (ivi: 0, nid: 0x67, ctl: 1, ttl: 6, seq: 14356, src: 0003, dst: 0F00, transportPdu: 0x636E1E592CE148, netMic: 0xB90EC050304358D2) received
ACK (seqZero: 1265, ackedSegments: 0x0000003F) received (decrypted using key: Primary Network Key (index: 0))

// Finally, ACKs seem to stop, but the previous message is sent again
<- 0x0067D2D6E72508F1C14CC148A0ED5C06C12DB63AA95A2CC689
Network PDU (ivi: 0, nid: 0x67, ctl: 0, ttl: 6, seq: 14357, src: 0003, dst: 0F00, transportPdu: 0xC148A0ED5C06C12DB63AA9, netMic: 0x5A2CC689) received
Discarding packet (seqAuth: 14351, expected > 14356)

As the last ACK increased the SEQ for the device to 14356 the phone discards the packet. Instead, it should process, check that it is the same segment repeated, and resend ACK. Otherwise the transmitter will not be able to proceed with next message.

The change removes the check for received and local SeqAuth, allowing some packets to come in between.

Note

I'm not 100% it's not a bug on the device side, that it's sending some packets in-between another transfer, but as others also experienced discarding packets, this change should help.

[philips77]

The second commit fixes the real issue shown the log above:

// Finally, ACKs seem to stop, but the previous message is sent again
<- 0x0067D2D6E72508F1C14CC148A0ED5C06C12DB63AA95A2CC689
Network PDU (ivi: 0, nid: 0x67, ctl: 0, ttl: 6, seq: 14357, src: 0003, dst: 0F00, transportPdu: 0xC148A0ED5C06C12DB63AA9, netMic: 0x5A2CC689) received
Discarding packet (seqAuth: 14351, expected > 14356)

This packet should have been accepted, as it's SeqAuth is higher than any previous. Before, for segments of segmented messages the message SeqAth (calculated using SeqZero) was taken for comparison. If any other message was received for the node before the segment, which would increase the SEQ value for the node, the segment would be discarded, just like it happened on the log.

After the change the SeqAuth is compared, but if reassembly is in progress segments of the segmented message are also accepted, even when sent it a different order.