iOS mesh app discarding packets due to sequence number

[ftjandra]

Hi,

We have built an iOS app with the iOS nRF Mesh Library (https://github.com/NordicSemiconductor/IOS-nRF-Mesh-Library) that collects data from all the sensors in the mesh network through a proxy node connected to an iPad.

We have a problem with sensor packets getting discarded due to their sequence number being lower than what the app expects.

I understand that this is to prevent replay attacks and to filter out duplicate packets, but I don't understand what would cause the expected sequence numbers to suddenly jump so far ahead.

I added a debug print on the sensor node to print out its sequence number and everything looks good here. I print out m_net_state.seqnum at this point here: https://github.com/NordicSemiconductor/nRF5-SDK-for-Mesh/blob/08c60f6d8766bdb83bb108ec3fbd24d758689235/mesh/core/src/net_state.c#L584

I also tried changing NETWORK_SEQNUM_FLASH_BLOCK_SIZE to 512 with no difference. I really don't think there is a problem on the sensor node side (SDK16.0.0 + Mesh SDK 4.1.0)

When the iOS app receives sequence number 8191, it suddenly increments the next expected sequence number to 16383. This causes the packets from the node to be discarded until it catches up. But it never does because once it reaches 16383, the expected suddenly jumps again to 24572. This seems to go on forever.

I modified checkAgainstReplayAttack() in LowerTransportLayer.swift to print out the received sequence number:

    func checkAgainstReplayAttack(_ networkPdu: NetworkPdu) -> Bool {
        // Don't check messages sent to another Node's Elements.
        guard !networkPdu.destination.isUnicast ||
              meshNetwork.localProvisioner?.node?.hasAllocatedAddress(networkPdu.destination) ?? false else {
            return true
        }
        let sequence = networkPdu.messageSequence
        let receivedSeqAuth = (UInt64(networkPdu.ivIndex) << 24) | UInt64(sequence)
        let networkPduIvIndex = UInt64(networkPdu.ivIndex)
        let sequenceTemp = UInt64(sequence)
        logger?.w(.lowerTransport, "Received receivedSeqAuth: \(receivedSeqAuth), \(networkPduIvIndex), \(sequenceTemp), \(sequence)")
        
        if let localSeqAuth = defaults.object(forKey: networkPdu.source.hex) as? NSNumber {
            // 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
            }
            guard receivedSeqAuth > localSeqAuth.uint64Value ||
                  (reassemblyInProgress && receivedSeqAuth == localSeqAuth.uint64Value) else {
                // Ignore that message.
                logger?.w(.lowerTransport, "Discarding packet (seqAuth: \(receivedSeqAuth), expected > \(localSeqAuth))")
                return false
            }
        }
        // SeqAuth is valid, save the new sequence authentication value.
        defaults.set(NSNumber(value: receivedSeqAuth), forKey: networkPdu.source.hex)
        logger?.w(.lowerTransport, "Stored receivedSeqAuth: \(receivedSeqAuth)")
        return true
    }

Right after it receives 8191, it says it receives 16383, but I don't see how that is possible since the debug prints on the sensor side don't show this.

2020-10-06 17:23:05.331223-0600 App[2583:1045319] [Bearer] <- 0x00555B806C25E168035C126C7174FCB6BA681506344A091F4A07B146DFFF
2020-10-06 17:23:05.332022-0600 App[2583:1045319] [Bearer] <- 0x0055FD4832C13F7517841E29170E7FE30EA314FA05F2A86C1C
2020-10-06 17:23:05.334603-0600 App[2583:1054306] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 8189, src: 0002, dst: C849, transportPdu: 0x126C7174FCB6BA681506344A091F4A07, netMic: 0xB146DFFF) received
2020-10-06 17:23:05.334794-0600 App[2583:1053303] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 8190, src: 0002, dst: C849, transportPdu: 0x1E29170E7FE30EA314FA05, netMic: 0xF2A86C1C) received
2020-10-06 17:23:05.335068-0600 App[2583:1054306] [LowerTransport] Received receivedSeqAuth: 8181, 0, 8181, 8181
2020-10-06 17:23:05.336940-0600 App[2583:1054306] [LowerTransport] Stored receivedSeqAuth: 8181
2020-10-06 17:23:05.338680-0600 App[2583:1054306] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8181, segO: 0, segN: 1, data: 0xB2FF2054492E2726C759659A) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 17:23:05.339437-0600 App[2583:1054306] [LowerTransport] Access Message (akf: 1, aid: 0x18, szmic: 0, data: 0xB2FF2054492E2726C759659A99825A80DB6A43) received
2020-10-06 17:23:05.340042-0600 App[2583:1053303] [LowerTransport] Received receivedSeqAuth: 8181, 0, 8181, 8181
2020-10-06 17:23:05.340841-0600 App[2583:1053303] [LowerTransport] Discarding packet (seqAuth: 8181, expected > 8181)
2020-10-06 17:23:05.341708-0600 App[2583:1053303] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8181, segO: 1, segN: 1, data: 0x99825A80DB6A43) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 17:23:05.342214-0600 App[2583:1054306] [UpperTransport] Upper Transport PDU (encrypted data: 0xB2FF2054492E2726C759659A99825A, transMic: 0x80DB6A43) received
2020-10-06 17:23:05.343070-0600 App[2583:1054306] [Access] Access PDU (opcode: 0x8204, parameters: 0xA7AD8C3F020178F268F42C0181) receieved (decrypted using key: Main App Key (index: 0))
UnknownMessage(opCode: 0x008204, parameters: A7AD8C3F020178F268F42C0181)
"A7AD8C3F020178F268F42C0181"
2020-10-06 17:23:06.321226-0600 App[2583:1045319] [Bearer] <- 0x005582E8C758D7B252F0FF9008F13DD28250D1DF8999378B3E454FD7ED03
2020-10-06 17:23:06.322128-0600 App[2583:1045319] [Bearer] <- 0x0055AA938A28AF10B931DBE8467E1D7217ABEB8A3B47C237EA
2020-10-06 17:23:06.323340-0600 App[2583:1054306] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 8191, src: 0002, dst: C849, transportPdu: 0xFF9008F13DD28250D1DF8999378B3E45, netMic: 0x4FD7ED03) received
2020-10-06 17:23:06.323526-0600 App[2583:1054306] [LowerTransport] Received receivedSeqAuth: 8191, 0, 8191, 8191
2020-10-06 17:23:06.323687-0600 App[2583:1053303] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 8192, src: 0002, dst: C849, transportPdu: 0xDBE8467E1D7217ABEB8A3B, netMic: 0x47C237EA) received
2020-10-06 17:23:06.327032-0600 App[2583:1054306] [LowerTransport] Stored receivedSeqAuth: 8191
2020-10-06 17:23:06.328409-0600 App[2583:1054306] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8191, segO: 0, segN: 1, data: 0x959CAAF488A2BA5BACA7847B) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 17:23:06.328989-0600 App[2583:1053303] [LowerTransport] Received receivedSeqAuth: 16383, 0, 16383, 16383
2020-10-06 17:23:06.332614-0600 App[2583:1053303] [LowerTransport] Stored receivedSeqAuth: 16383
2020-10-06 17:23:06.333849-0600 App[2583:1053303] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8191, segO: 1, segN: 1, data: 0x6C6634BF0A3484) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 17:23:06.334619-0600 App[2583:1053303] [LowerTransport] Access Message (akf: 1, aid: 0x18, szmic: 0, data: 0x959CAAF488A2BA5BACA7847B6C6634BF0A3484) received
2020-10-06 17:23:06.336211-0600 App[2583:1053303] [UpperTransport] Upper Transport PDU (encrypted data: 0x959CAAF488A2BA5BACA7847B6C6634, transMic: 0xBF0A3484) received
2020-10-06 17:23:06.336716-0600 App[2583:1053303] [Access] Access PDU (opcode: 0x8204, parameters: 0xA7AD8C3F020178F368F42C0181) receieved (decrypted using key: Main App Key (index: 0))
UnknownMessage(opCode: 0x008204, parameters: A7AD8C3F020178F368F42C0181)
"A7AD8C3F020178F368F42C0181"
2020-10-06 17:23:06.815344-0600 App[2583:1045319] [Bearer] <- 0x0055641949D25BF7D1061AEF174157526F3CDDEBE935B6AD0427855148EB
2020-10-06 17:23:06.816037-0600 App[2583:1045319] [Bearer] <- 0x0055EAD052E1D87D85E615A9FD3068BB4D7EB5498E09076957
2020-10-06 17:23:06.816347-0600 App[2583:1053303] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 8193, src: 0002, dst: C849, transportPdu: 0x1AEF174157526F3CDDEBE935B6AD0427, netMic: 0x855148EB) received
2020-10-06 17:23:06.816451-0600 App[2583:1053303] [LowerTransport] Received receivedSeqAuth: 16383, 0, 16383, 16383
2020-10-06 17:23:06.816906-0600 App[2583:1054306] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 8194, src: 0002, dst: C849, transportPdu: 0x15A9FD3068BB4D7EB5498E, netMic: 0x09076957) received
2020-10-06 17:23:06.817364-0600 App[2583:1053303] [LowerTransport] Discarding packet (seqAuth: 16383, expected > 16383)
2020-10-06 17:23:06.818035-0600 App[2583:1053303] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8191, segO: 0, segN: 1, data: 0x959CAAF488A2BA5BACA7847B) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 17:23:06.818314-0600 App[2583:1054306] [LowerTransport] Received receivedSeqAuth: 16383, 0, 16383, 16383
2020-10-06 17:23:06.818974-0600 App[2583:1054306] [LowerTransport] Stored receivedSeqAuth: 16383
2020-10-06 17:23:06.819428-0600 App[2583:1054306] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8191, segO: 1, segN: 1, data: 0x6C6634BF0A3484) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 17:23:06.820023-0600 App[2583:1054306] [LowerTransport] Access Message (akf: 1, aid: 0x18, szmic: 0, data: 0x959CAAF488A2BA5BACA7847B6C6634BF0A3484) received
2020-10-06 17:23:06.823167-0600 App[2583:1054306] [UpperTransport] Failed to decode PDU
2020-10-06 17:23:07.310057-0600 App[2583:1045319] [Bearer] <- 0x0055D5AB3BD63CF77A63C9F310F863C6D051971825CB5338657DEAB8816C
2020-10-06 17:23:07.368563-0600 App[2583:1054306] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 8195, src: 0002, dst: C849, transportPdu: 0xC9F310F863C6D051971825CB5338657D, netMic: 0xEAB8816C) received
2020-10-06 17:23:07.369163-0600 App[2583:1054306] [LowerTransport] Received receivedSeqAuth: 16383, 0, 16383, 16383
2020-10-06 17:23:07.370374-0600 App[2583:1054306] [LowerTransport] Discarding packet (seqAuth: 16383, expected > 16383)
2020-10-06 17:23:07.371183-0600 App[2583:1054306] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8191, segO: 0, segN: 1, data: 0x959CAAF488A2BA5BACA7847B) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 17:23:07.557754-0600 App[2583:1045319] [Bearer] <- 0x00552C760033F6617A5E5984277A15FD97252A061E6612F13F
2020-10-06 17:23:07.558462-0600 App[2583:1054306] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 8196, src: 0002, dst: C849, transportPdu: 0x5984277A15FD97252A061E, netMic: 0x6612F13F) received
2020-10-06 17:23:07.558563-0600 App[2583:1054306] [LowerTransport] Received receivedSeqAuth: 16383, 0, 16383, 16383
2020-10-06 17:23:07.559538-0600 App[2583:1054306] [LowerTransport] Stored receivedSeqAuth: 16383
2020-10-06 17:23:07.560271-0600 App[2583:1054306] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8191, segO: 1, segN: 1, data: 0x6C6634BF0A3484) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 17:23:07.560572-0600 App[2583:1054306] [LowerTransport] Access Message (akf: 1, aid: 0x18, szmic: 0, data: 0x959CAAF488A2BA5BACA7847B6C6634BF0A3484) received
2020-10-06 17:23:07.560976-0600 App[2583:1054306] [UpperTransport] Failed to decode PDU
2020-10-06 17:23:07.805064-0600 App[2583:1045319] [Bearer] <- 0x0055497A0BBCE4AAF1B777775E0BD95DBF9211834BE255DA5E6C0772F9D6
2020-10-06 17:23:07.806073-0600 App[2583:1054306] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 8197, src: 0002, dst: C849, transportPdu: 0x77775E0BD95DBF9211834BE255DA5E6C, netMic: 0x0772F9D6) received
2020-10-06 17:23:07.806132-0600 App[2583:1045319] [Bearer] <- 0x0055DB1215D4629289926A314BFEE5F2C4041EB041261E28EE
2020-10-06 17:23:07.806294-0600 App[2583:1054306] [LowerTransport] Received receivedSeqAuth: 16383, 0, 16383, 16383
2020-10-06 17:23:07.807036-0600 App[2583:1054306] [LowerTransport] Discarding packet (seqAuth: 16383, expected > 16383)
2020-10-06 17:23:07.807153-0600 App[2583:1053303] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 8198, src: 0002, dst: C849, transportPdu: 0x6A314BFEE5F2C4041EB041, netMic: 0x261E28EE) received
2020-10-06 17:23:07.807907-0600 App[2583:1054306] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8191, segO: 0, segN: 1, data: 0x959CAAF488A2BA5BACA7847B) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 17:23:07.808080-0600 App[2583:1053303] [LowerTransport] Received receivedSeqAuth: 16383, 0, 16383, 16383
2020-10-06 17:23:07.808810-0600 App[2583:1053303] [LowerTransport] Stored receivedSeqAuth: 16383
2020-10-06 17:23:07.809545-0600 App[2583:1053303] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8191, segO: 1, segN: 1, data: 0x6C6634BF0A3484) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 17:23:07.809841-0600 App[2583:1053303] [LowerTransport] Access Message (akf: 1, aid: 0x18, szmic: 0, data: 0x959CAAF488A2BA5BACA7847B6C6634BF0A3484) received
2020-10-06 17:23:07.810299-0600 App[2583:1053303] [UpperTransport] Failed to decode PDU
2020-10-06 17:23:08.300333-0600 App[2583:1045319] [Bearer] <- 0x0055DC4952DB5C97E4B16F355DC410E60AD76C769ABF8222E5196E4C2261
2020-10-06 17:23:08.301367-0600 App[2583:1045319] [Bearer] <- 0x0055C14AA5CD13CA9EDF0FAA9A99F926C31FB687A463456550
2020-10-06 17:23:08.302150-0600 App[2583:1053303] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 8199, src: 0002, dst: C849, transportPdu: 0x6F355DC410E60AD76C769ABF8222E519, netMic: 0x6E4C2261) received
2020-10-06 17:23:08.302278-0600 App[2583:1053303] [LowerTransport] Received receivedSeqAuth: 16383, 0, 16383, 16383
2020-10-06 17:23:08.303229-0600 App[2583:1054306] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 8200, src: 0002, dst: C849, transportPdu: 0x0FAA9A99F926C31FB687A4, netMic: 0x63456550) received
2020-10-06 17:23:08.303260-0600 App[2583:1053303] [LowerTransport] Discarding packet (seqAuth: 16383, expected > 16383)
2020-10-06 17:23:08.304069-0600 App[2583:1053303] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8191, segO: 0, segN: 1, data: 0x959CAAF488A2BA5BACA7847B) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 17:23:08.304709-0600 App[2583:1054306] [LowerTransport] Received receivedSeqAuth: 16383, 0, 16383, 16383
2020-10-06 17:23:08.305563-0600 App[2583:1054306] [LowerTransport] Stored receivedSeqAuth: 16383
2020-10-06 17:23:08.306171-0600 App[2583:1054306] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8191, segO: 1, segN: 1, data: 0x6C6634BF0A3484) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 17:23:08.306505-0600 App[2583:1054306] [LowerTransport] Access Message (akf: 1, aid: 0x18, szmic: 0, data: 0x959CAAF488A2BA5BACA7847B6C6634BF0A3484) received
2020-10-06 17:23:08.307016-0600 App[2583:1054306] [UpperTransport] Failed to decode PDU
2020-10-06 17:23:09.290740-0600 App[2583:1045319] [Bearer] <- 0x005574AD385C80700B0ACA9599742B0FA9B8E1C799BC11B034CD5556B1A5
2020-10-06 17:23:09.291600-0600 App[2583:1054306] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 8201, src: 0002, dst: C849, transportPdu: 0xCA9599742B0FA9B8E1C799BC11B034CD, netMic: 0x5556B1A5) received
2020-10-06 17:23:09.291717-0600 App[2583:1054306] [LowerTransport] Received receivedSeqAuth: 8201, 0, 8201, 8201
2020-10-06 17:23:09.292547-0600 App[2583:1054306] [LowerTransport] Discarding packet (seqAuth: 8201, expected > 16383)
2020-10-06 17:23:09.293257-0600 App[2583:1054306] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 9, segO: 0, segN: 1, data: 0x1E5EC7DEED610B26D3017096) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 17:23:09.540012-0600 App[2583:1045319] [Bearer] <- 0x0055C387D47C7CB7F6FB8AE11E0A9576F14450AAA5EB769839
2020-10-06 17:23:09.541870-0600 App[2583:1054306] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 8202, src: 0002, dst: C849, transportPdu: 0x8AE11E0A9576F14450AAA5, netMic: 0xEB769839) received
2020-10-06 17:23:09.542157-0600 App[2583:1054306] [LowerTransport] Received receivedSeqAuth: 8201, 0, 8201, 8201
2020-10-06 17:23:09.543685-0600 App[2583:1054306] [LowerTransport] Discarding packet (seqAuth: 8201, expected > 16383)
2020-10-06 17:23:09.546327-0600 App[2583:1054306] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 9, segO: 1, segN: 1, data: 0x896B4BF171A9E8) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 17:23:09.548237-0600 App[2583:1054306] [LowerTransport] Access Message (akf: 1, aid: 0x18, szmic: 0, data: 0x1E5EC7DEED610B26D3017096896B4BF171A9E8) received
2020-10-06 17:23:09.549439-0600 App[2583:1054306] [UpperTransport] Upper Transport PDU (encrypted data: 0x1E5EC7DEED610B26D3017096896B4B, transMic: 0xF171A9E8) received
2020-10-06 17:23:09.550436-0600 App[2583:1054306] [Access] Access PDU (opcode: 0x8204, parameters: 0xA7AD8C3F020178F368F42C0181) receieved (decrypted using key: Main App Key (index: 0))
UnknownMessage(opCode: 0x008204, parameters: A7AD8C3F020178F368F42C0181)
"A7AD8C3F020178F368F42C0181"

Then after it receives 16380 it says it received 24572.

2020-10-06 18:04:00.274096-0600 App[2620:1062278] [LowerTransport] Received receivedSeqAuth: 16370, 0, 16370, 16370
2020-10-06 18:04:00.273904-0600 App[2620:1062524] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 16380, src: 0002, dst: C849, transportPdu: 0x512FA2006E6340D20368460B064780AF, netMic: 0x3C00C462) received
2020-10-06 18:04:00.276591-0600 App[2620:1062278] [LowerTransport] Discarding packet (seqAuth: 16370, expected > 16383)
2020-10-06 18:04:00.277808-0600 App[2620:1062278] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8178, segO: 1, segN: 1, data: 0x85107A46F6F1FB) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:00.279092-0600 App[2620:1062278] [LowerTransport] Access Message (akf: 1, aid: 0x18, szmic: 0, data: 0x13C38A5CD97785FB58D87FCE85107A46F6F1FB) received
2020-10-06 18:04:00.280090-0600 App[2620:1063066] [LowerTransport] Received receivedSeqAuth: 16380, 0, 16380, 16380
2020-10-06 18:04:00.281393-0600 App[2620:1063066] [LowerTransport] Discarding packet (seqAuth: 16380, expected > 16383)
2020-10-06 18:04:00.282973-0600 App[2620:1062278] [UpperTransport] Upper Transport PDU (encrypted data: 0x13C38A5CD97785FB58D87FCE85107A, transMic: 0x46F6F1FB) received
2020-10-06 18:04:00.283045-0600 App[2620:1063066] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8188, segO: 1, segN: 1, data: 0xC0C77E9DE8C868) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:00.283581-0600 App[2620:1062524] [LowerTransport] Received receivedSeqAuth: 16380, 0, 16380, 16380
2020-10-06 18:04:00.283884-0600 App[2620:1062278] [Access] Access PDU (opcode: 0x8204, parameters: 0xA7AD8C3F020179F26BF42C0181) receieved (decrypted using key: Main App Key (index: 0))
2020-10-06 18:04:00.286598-0600 App[2620:1062524] [LowerTransport] Discarding packet (seqAuth: 16380, expected > 16383)
UnknownMessage(opCode: 0x008204, parameters: A7AD8C3F020179F26BF42C0181)
"A7AD8C3F020179F26BF42C0181"
2020-10-06 18:04:00.289599-0600 App[2620:1062524] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8188, segO: 0, segN: 1, data: 0x0DC570FF98AF218D51231D9D) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:00.290265-0600 App[2620:1062524] [LowerTransport] Access Message (akf: 1, aid: 0x18, szmic: 0, data: 0x0DC570FF98AF218D51231D9DC0C77E9DE8C868) received
2020-10-06 18:04:00.291800-0600 App[2620:1062524] [UpperTransport] Upper Transport PDU (encrypted data: 0x0DC570FF98AF218D51231D9DC0C77E, transMic: 0x9DE8C868) received
2020-10-06 18:04:00.292646-0600 App[2620:1062524] [Access] Access PDU (opcode: 0x8204, parameters: 0xA7AD8C3F020178F268F42C0181) receieved (decrypted using key: Main App Key (index: 0))
UnknownMessage(opCode: 0x008204, parameters: A7AD8C3F020178F268F42C0181)
"A7AD8C3F020178F268F42C0181"
2020-10-06 18:04:00.514684-0600 App[2620:1062104] [Bearer] <- 0x00552F88042CD7935B8215434C87CB599629BB44332AD135D1D01AB296F0
2020-10-06 18:04:00.515361-0600 App[2620:1063066] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 16382, src: 0002, dst: C849, transportPdu: 0x15434C87CB599629BB44332AD135D1D0, netMic: 0x1AB296F0) received
2020-10-06 18:04:00.515481-0600 App[2620:1063066] [LowerTransport] Received receivedSeqAuth: 16380, 0, 16380, 16380
2020-10-06 18:04:00.516059-0600 App[2620:1063066] [LowerTransport] Discarding packet (seqAuth: 16380, expected > 16383)
2020-10-06 18:04:00.516591-0600 App[2620:1063066] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8188, segO: 0, segN: 1, data: 0x0DC570FF98AF218D51231D9D) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:00.762317-0600 App[2620:1062104] [Bearer] <- 0x0055743720EDE9326D50631F25E349E545BC6A45CD90536610
2020-10-06 18:04:00.762980-0600 App[2620:1063066] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 16383, src: 0002, dst: C849, transportPdu: 0x631F25E349E545BC6A45CD, netMic: 0x90536610) received
2020-10-06 18:04:00.763108-0600 App[2620:1063066] [LowerTransport] Received receivedSeqAuth: 16380, 0, 16380, 16380
2020-10-06 18:04:00.763686-0600 App[2620:1063066] [LowerTransport] Discarding packet (seqAuth: 16380, expected > 16383)
2020-10-06 18:04:00.764240-0600 App[2620:1063066] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8188, segO: 1, segN: 1, data: 0xC0C77E9DE8C868) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:00.764798-0600 App[2620:1063066] [LowerTransport] Access Message (akf: 1, aid: 0x18, szmic: 0, data: 0x0DC570FF98AF218D51231D9DC0C77E9DE8C868) received
2020-10-06 18:04:00.765313-0600 App[2620:1063066] [UpperTransport] Upper Transport PDU (encrypted data: 0x0DC570FF98AF218D51231D9DC0C77E, transMic: 0x9DE8C868) received
2020-10-06 18:04:00.765626-0600 App[2620:1063066] [Access] Access PDU (opcode: 0x8204, parameters: 0xA7AD8C3F020178F268F42C0181) receieved (decrypted using key: Main App Key (index: 0))
UnknownMessage(opCode: 0x008204, parameters: A7AD8C3F020178F268F42C0181)
"A7AD8C3F020178F268F42C0181"
2020-10-06 18:04:01.009721-0600 App[2620:1062104] [Bearer] <- 0x0055D05CC271ECEA06313462AEF1CA3EF6657AD090442C0D336503A55F40
2020-10-06 18:04:01.010483-0600 App[2620:1063066] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 16384, src: 0002, dst: C849, transportPdu: 0x3462AEF1CA3EF6657AD090442C0D3365, netMic: 0x03A55F40) received
2020-10-06 18:04:01.010580-0600 App[2620:1063066] [LowerTransport] Received receivedSeqAuth: 24572, 0, 24572, 24572
2020-10-06 18:04:01.012227-0600 App[2620:1063066] [LowerTransport] Stored receivedSeqAuth: 24572
2020-10-06 18:04:01.012809-0600 App[2620:1063066] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8188, segO: 0, segN: 1, data: 0x0DC570FF98AF218D51231D9D) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:01.257618-0600 App[2620:1062104] [Bearer] <- 0x0055A8AEE965EF746341312E86F9849207C8792D5B6E281CEE
2020-10-06 18:04:01.258400-0600 App[2620:1063066] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 16385, src: 0002, dst: C849, transportPdu: 0x312E86F9849207C8792D5B, netMic: 0x6E281CEE) received
2020-10-06 18:04:01.258517-0600 App[2620:1063066] [LowerTransport] Received receivedSeqAuth: 24572, 0, 24572, 24572
2020-10-06 18:04:01.259528-0600 App[2620:1063066] [LowerTransport] Stored receivedSeqAuth: 24572
2020-10-06 18:04:01.260198-0600 App[2620:1063066] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8188, segO: 1, segN: 1, data: 0xC0C77E9DE8C868) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:01.260748-0600 App[2620:1063066] [LowerTransport] Access Message (akf: 1, aid: 0x18, szmic: 0, data: 0x0DC570FF98AF218D51231D9DC0C77E9DE8C868) received
2020-10-06 18:04:01.261164-0600 App[2620:1063066] [UpperTransport] Failed to decode PDU
2020-10-06 18:04:01.505264-0600 App[2620:1062104] [Bearer] <- 0x00559A7235438CAD7B61DCFEB4B624991C685856948684058E9CAA152609
2020-10-06 18:04:01.506144-0600 App[2620:1062104] [Bearer] <- 0x0055093F666024D06A418A87C804055546E13923CB4EA11FC6
2020-10-06 18:04:01.506830-0600 App[2620:1062278] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 16386, src: 0002, dst: C849, transportPdu: 0xDCFEB4B624991C685856948684058E9C, netMic: 0xAA152609) received
2020-10-06 18:04:01.506998-0600 App[2620:1063066] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 16387, src: 0002, dst: C849, transportPdu: 0x8A87C804055546E13923CB, netMic: 0x4EA11FC6) received
2020-10-06 18:04:01.507164-0600 App[2620:1062278] [LowerTransport] Received receivedSeqAuth: 24572, 0, 24572, 24572
2020-10-06 18:04:01.508314-0600 App[2620:1062278] [LowerTransport] Discarding packet (seqAuth: 24572, expected > 24572)
2020-10-06 18:04:01.509378-0600 App[2620:1062278] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8188, segO: 0, segN: 1, data: 0x0DC570FF98AF218D51231D9D) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:01.509760-0600 App[2620:1063066] [LowerTransport] Received receivedSeqAuth: 24572, 0, 24572, 24572
2020-10-06 18:04:01.510839-0600 App[2620:1063066] [LowerTransport] Stored receivedSeqAuth: 24572
2020-10-06 18:04:01.511654-0600 App[2620:1063066] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8188, segO: 1, segN: 1, data: 0xC0C77E9DE8C868) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:01.512233-0600 App[2620:1063066] [LowerTransport] Access Message (akf: 1, aid: 0x18, szmic: 0, data: 0x0DC570FF98AF218D51231D9DC0C77E9DE8C868) received
2020-10-06 18:04:01.512730-0600 App[2620:1063066] [UpperTransport] Failed to decode PDU
2020-10-06 18:04:02.000735-0600 App[2620:1062104] [Bearer] <- 0x0055740FC5F4E1E1192E3B3C5C9CE27BFD35AE81AE6423F38FFA42AB422F
2020-10-06 18:04:02.001562-0600 App[2620:1062104] [Bearer] <- 0x00552CE33D37B20910445602FCD99341E3EDCC397C157C9BD4
2020-10-06 18:04:02.003000-0600 App[2620:1063066] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 16388, src: 0002, dst: C849, transportPdu: 0x3B3C5C9CE27BFD35AE81AE6423F38FFA, netMic: 0x42AB422F) received
2020-10-06 18:04:02.003170-0600 App[2620:1063066] [LowerTransport] Received receivedSeqAuth: 24572, 0, 24572, 24572
2020-10-06 18:04:02.004582-0600 App[2620:1063066] [LowerTransport] Discarding packet (seqAuth: 24572, expected > 24572)
2020-10-06 18:04:02.005822-0600 App[2620:1062278] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 16389, src: 0002, dst: C849, transportPdu: 0x5602FCD99341E3EDCC397C, netMic: 0x157C9BD4) received
2020-10-06 18:04:02.005965-0600 App[2620:1063066] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8188, segO: 0, segN: 1, data: 0x0DC570FF98AF218D51231D9D) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:02.006551-0600 App[2620:1062278] [LowerTransport] Received receivedSeqAuth: 24572, 0, 24572, 24572
2020-10-06 18:04:02.008015-0600 App[2620:1062278] [LowerTransport] Stored receivedSeqAuth: 24572
2020-10-06 18:04:02.009074-0600 App[2620:1062278] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 8188, segO: 1, segN: 1, data: 0xC0C77E9DE8C868) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:02.009699-0600 App[2620:1062278] [LowerTransport] Access Message (akf: 1, aid: 0x18, szmic: 0, data: 0x0DC570FF98AF218D51231D9DC0C77E9DE8C868) received
2020-10-06 18:04:02.010253-0600 App[2620:1062278] [UpperTransport] Failed to decode PDU
2020-10-06 18:04:03.239496-0600 App[2620:1062104] [Bearer] <- 0x005579F8776DBA9BE5C52FA6B2A3F91CB7CE13823E73B8FA08F76409BD45
2020-10-06 18:04:03.240607-0600 App[2620:1062104] [Bearer] <- 0x0055217520A04EBD9F0A66CB047EC70DCE0BA0132AFAB2E93C
2020-10-06 18:04:03.242324-0600 App[2620:1063066] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 16391, src: 0002, dst: C849, transportPdu: 0x66CB047EC70DCE0BA0132A, netMic: 0xFAB2E93C) received
2020-10-06 18:04:03.242568-0600 App[2620:1063066] [LowerTransport] Received receivedSeqAuth: 16390, 0, 16390, 16390
2020-10-06 18:04:03.242764-0600 App[2620:1062278] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 16390, src: 0002, dst: C849, transportPdu: 0x2FA6B2A3F91CB7CE13823E73B8FA08F7, netMic: 0x6409BD45) received
2020-10-06 18:04:03.245296-0600 App[2620:1063066] [LowerTransport] Discarding packet (seqAuth: 16390, expected > 24572)
2020-10-06 18:04:03.246974-0600 App[2620:1063066] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 6, segO: 1, segN: 1, data: 0xBB53C2A1AE12C1) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:03.247814-0600 App[2620:1062278] [LowerTransport] Received receivedSeqAuth: 16390, 0, 16390, 16390
2020-10-06 18:04:03.249318-0600 App[2620:1062278] [LowerTransport] Discarding packet (seqAuth: 16390, expected > 24572)
2020-10-06 18:04:03.251287-0600 App[2620:1062278] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 6, segO: 0, segN: 1, data: 0x777BF03655EDCFC74F86E87D) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:03.252269-0600 App[2620:1062278] [LowerTransport] Access Message (akf: 1, aid: 0x18, szmic: 0, data: 0x777BF03655EDCFC74F86E87DBB53C2A1AE12C1) received
2020-10-06 18:04:03.254131-0600 App[2620:1062278] [UpperTransport] Upper Transport PDU (encrypted data: 0x777BF03655EDCFC74F86E87DBB53C2, transMic: 0xA1AE12C1) received
2020-10-06 18:04:03.255165-0600 App[2620:1062278] [Access] Access PDU (opcode: 0x8204, parameters: 0xA7AD8C3F020178F268F42C0181) receieved (decrypted using key: Main App Key (index: 0))
UnknownMessage(opCode: 0x008204, parameters: A7AD8C3F020178F268F42C0181)
"A7AD8C3F020178F268F42C0181"
2020-10-06 18:04:03.485808-0600 App[2620:1062104] [Bearer] <- 0x00555D2610A329C4A9FF523B36BFD0A090E48B60131434D21702D31BBFDB
2020-10-06 18:04:03.486674-0600 App[2620:1062104] [Bearer] <- 0x0055FBB4816A9525E3F80EC62EB7C9CFB60051D4B0617A2F45
2020-10-06 18:04:03.487783-0600 App[2620:1062278] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 16392, src: 0002, dst: C849, transportPdu: 0x523B36BFD0A090E48B60131434D21702, netMic: 0xD31BBFDB) received
2020-10-06 18:04:03.488112-0600 App[2620:1062278] [LowerTransport] Received receivedSeqAuth: 16390, 0, 16390, 16390
2020-10-06 18:04:03.488223-0600 App[2620:1063066] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 16393, src: 0002, dst: C849, transportPdu: 0x0EC62EB7C9CFB60051D4B0, netMic: 0x617A2F45) received
2020-10-06 18:04:03.489642-0600 App[2620:1062278] [LowerTransport] Discarding packet (seqAuth: 16390, expected > 24572)
2020-10-06 18:04:03.490760-0600 App[2620:1062278] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 6, segO: 0, segN: 1, data: 0x777BF03655EDCFC74F86E87D) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:03.491368-0600 App[2620:1063066] [LowerTransport] Received receivedSeqAuth: 16390, 0, 16390, 16390
2020-10-06 18:04:03.492263-0600 App[2620:1063066] [LowerTransport] Discarding packet (seqAuth: 16390, expected > 24572)
2020-10-06 18:04:03.493413-0600 App[2620:1063066] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 6, segO: 1, segN: 1, data: 0xBB53C2A1AE12C1) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:03.494090-0600 App[2620:1063066] [LowerTransport] Access Message (akf: 1, aid: 0x18, szmic: 0, data: 0x777BF03655EDCFC74F86E87DBB53C2A1AE12C1) received
2020-10-06 18:04:03.495358-0600 App[2620:1063066] [UpperTransport] Upper Transport PDU (encrypted data: 0x777BF03655EDCFC74F86E87DBB53C2, transMic: 0xA1AE12C1) received
2020-10-06 18:04:03.495855-0600 App[2620:1063066] [Access] Access PDU (opcode: 0x8204, parameters: 0xA7AD8C3F020178F268F42C0181) receieved (decrypted using key: Main App Key (index: 0))
UnknownMessage(opCode: 0x008204, parameters: A7AD8C3F020178F268F42C0181)
"A7AD8C3F020178F268F42C0181"
2020-10-06 18:04:04.228684-0600 App[2620:1062104] [Bearer] <- 0x005540A01C378EC537DFEB38785A1B5E76C38F7CDEFB6B40900F39B0F37E
2020-10-06 18:04:04.229781-0600 App[2620:1062104] [Bearer] <- 0x005564D7077530F39FCB350767DACCFB0645F9FE71DFC28153
2020-10-06 18:04:04.230537-0600 App[2620:1063066] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 16394, src: 0002, dst: C849, transportPdu: 0xEB38785A1B5E76C38F7CDEFB6B40900F, netMic: 0x39B0F37E) received
2020-10-06 18:04:04.230781-0600 App[2620:1063066] [LowerTransport] Received receivedSeqAuth: 16390, 0, 16390, 16390
2020-10-06 18:04:04.232018-0600 App[2620:1062278] [Network] Network PDU (ivi: 0, nid: 0x55, ctl: 0, ttl: 4, seq: 16395, src: 0002, dst: C849, transportPdu: 0x350767DACCFB0645F9FE71, netMic: 0xDFC28153) received
2020-10-06 18:04:04.232160-0600 App[2620:1063066] [LowerTransport] Discarding packet (seqAuth: 16390, expected > 24572)
2020-10-06 18:04:04.233458-0600 App[2620:1063066] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 6, segO: 0, segN: 1, data: 0x777BF03655EDCFC74F86E87D) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:04.233951-0600 App[2620:1062278] [LowerTransport] Received receivedSeqAuth: 16390, 0, 16390, 16390
2020-10-06 18:04:04.234718-0600 App[2620:1062278] [LowerTransport] Discarding packet (seqAuth: 16390, expected > 24572)
2020-10-06 18:04:04.235946-0600 App[2620:1062278] [LowerTransport] Segmented Access Message (akf: 1, aid: 0x18, szmic: 0, seqZero: 6, segO: 1, segN: 1, data: 0xBB53C2A1AE12C1) receieved (decrypted using key: Primary Network Key (index: 0))
2020-10-06 18:04:04.236645-0600 App[2620:1062278] [LowerTransport] Access Message (akf: 1, aid: 0x18, szmic: 0, data: 0x777BF03655EDCFC74F86E87DBB53C2A1AE12C1) received
2020-10-06 18:04:04.237985-0600 App[2620:1062278] [UpperTransport] Upper Transport PDU (encrypted data: 0x777BF03655EDCFC74F86E87DBB53C2, transMic: 0xA1AE12C1) received
2020-10-06 18:04:04.238558-0600 App[2620:1062278] [Access] Access PDU (opcode: 0x8204, parameters: 0xA7AD8C3F020178F268F42C0181) receieved (decrypted using key: Main App Key (index: 0))
UnknownMessage(opCode: 0x008204, parameters: A7AD8C3F020178F268F42C0181)
"A7AD8C3F020178F268F42C0181"

What is going in here?

Thanks.

[Aleksander Nowakowski]

Hello,

What version of the library are you using?

I don't know what's going on, how that numbers can get like that. It is either something with threading or how it get compiled. What else is wrong on the logs is that those messages are segmented and have the same seqZero, so reassemblyInProgress should be true and you should never get log message Discarding... for those messages.

My recommendations:

- upgrade lib to 3.0-beta1. This method has been improved in that version and perhaps works better when 2 messages are received very in short interval and processed in 2 threads.

- or initialize MeshNetworkManager with serial processing queue. By default the global one is used which is concurrent.

[ftjandra]

Hi,

We are using 2.2.3. We just tried to use 3.0-beta1, but the app wont build and looks like a lot of things have changed and we will need to do quite a bit of rework. Is there a changelog of the changes?

What is the drawback of using a serial processing queue? Delays? Drops if the queue gets full?

Thanks.

[Aleksander Nowakowski]

If it indeed uses serial queue, that wasn't intended. I'll look into it.. when I'm back from my leave in mid January.

[Aleksander Nowakowski]

https://github.com/NordicSemiconductor/IOS-nRF-Mesh-Library/blob/0861ceba2cb13fa0e60960cd3a818efb5b852803/nRFMeshProvision/Classes/MeshNetworkManager.swift#L174

It's still concurrent queue.

[ftjandra]

For some reason I thought that DispatchQueues were serial by default. How would I modify this to make it a serial queue?

Thanks.

[Aleksander Nowakowski]

www.avanderlee.com/.../

[ftjandra]

So it looks like all I need to do is change that line to:

//queue: DispatchQueue = DispatchQueue.global(qos: .background),
queue: DispatchQueue = DispatchQueue(label: "serial"),

[Aleksander Nowakowski]

You don't need to modify the library. The queue can be given as a parameter in Manager's initializer.