[nrfconnect] fails to handle certain L2CAP connection update requests

[gjc13]

Problem

We found that certain LL_CONNECTION_UPDATE_REQ packets will cause the nrfconnect light-app to be unresponsive to any further BLE connection packets.

Bluetooth Low Energy Link Layer
Frame 3326: 38 bytes on wire (304 bits), 38 bytes captured (304 bits) on interface 0
Nordic BLE Sniffer
Bluetooth Low Energy Link Layer
    Access Address: 0x506564ae
    [Master Address: xxxxxxxx (xxxxxxxxxxxxxx)]
    [Slave Address: cf:97:0e:fd:3c:54 (cf:97:0e:fd:3c:54)]
    Data Header: 0x0c03
    Control Opcode: LL_CONNECTION_UPDATE_REQ (0x00)
    Window Size: 3
    Window Offset: 9
    Interval: 24
    Latency: 0
    Timeout: 500
    Instant: 14
    CRC: 0xe8d6e2

Proposed Solution

We need to dig into the zephyr BLE stack to know what's happening there.

[Damian-Nordic]

@gjc13 I'll take a look. Could you share more info on how you tested the app? Did you maybe check if any logs were printed at the time?

[gjc13]

This is the device log

uart:~$ I: nRF5 802154 radio initialized
I: 8 Sectors of 4096 bytes
I: alloc wra: 0, bd0
I: data wra: 0, 4e3
*** Booting Zephyr OS build v2.3.0-rc1-ncs1-2401-ga87b995bec87  ***
I: Init CHIP stack
I: SoftDevice Controller build revision: 
I: ea dd 23 d4 4a 32 a0 08 |..#.J2..
I: d2 8b c5 2e 65 57 e2 04 |....eW..
I: 69 53 03 e6             |iS..    
I: Starting CHIP task
I: Init Thread stack
I: 503[DL] OpenThread started: OK
I: 507[DL] Setup PIN code not found; using default: 012345678
D: 641[IN] New pairing for key 0!!
I: 645[SVR] Server Listening...
I: 648[DL] Setup PIN code not found; using default: 012345678
I: 654[DL] Setup PIN discriminator not found; using default: 07b
I: 660[SVR] SetupPINCode: [12345678]
I: 663[SVR] SetupQRCode:  [CH:I34DV* XQ8 B9SS0]
I: 667[DL] Setup PIN code not found; using default: 012345678
I: 673[DL] Setup PIN discriminator not found; using default: 07b
D: 679[DL] SetAdvertisingEnabled(true)
D: 682[DL] CHIP task running
D: 685[DL] In DriveBLEState
I: 688[DL] Setup PIN discriminator not found; using default: 07b
E: 694[DL] void chip::DeviceLayer::Internal::GenericThreadStackManagerImpl_Zephyr<ImplClass>::_OnCHIPoBLEAdvertisingStart() [with ImplClass = chip::DeviceLayer::ThreadStackManagerImpl]: NOT IMPLEMENTED
I: 715[DL] CHIPoBLE advertising started
D: 718[DL] In DriveBLEState
I: 26127[DL] BLE connection established (ConnId: 0x00)
I: 26132[DL] Current number of connections: 1/1
D: 26137[DL] In DriveBLEState
I: 26139[DL] Setup PIN discriminator not found; using default: 07b
I: 26568[DL] BLE GAP connection terminated (reason 0x2a)
I: 26573[DL] Current number of connections: 0/1
D: 26577[DL] In DriveBLEState
I: 26580[DL] Setup PIN discriminator not found; using default: 07b
I: 33975[DL] BLE connection established (ConnId: 0x00)
I: 33980[DL] Current number of connections: 1/1
D: 33984[DL] In DriveBLEState
I: 33987[DL] Setup PIN discriminator not found; using default: 07b
I: 34391[DL] BLE GAP connection terminated (reason 0x2a)
I: 34396[DL] Current number of connections: 0/1
D: 34401[DL] In DriveBLEState
I: 34403[DL] Setup PIN discriminator not found; using default: 07b

uart:~$ I: 42436[DL] BLE connection established (ConnId: 0x00)
I: 42441[DL] Current number of connections: 1/1
D: 42445[DL] In DriveBLEState
I: 42448[DL] Setup PIN discriminator not found; using default: 07b
I: 42856[DL] BLE GAP connection terminated (reason 0x2a)
I: 42861[DL] Current number of connections: 0/1
D: 42866[DL] In DriveBLEState
I: 42869[DL] Setup PIN discriminator not found; using default: 07b
I: 50472[DL] BLE connection established (ConnId: 0x00)
I: 50477[DL] Current number of connections: 1/1
D: 50481[DL] In DriveBLEState
I: 50484[DL] Setup PIN discriminator not found; using default: 07b
I: 50905[DL] BLE GAP connection terminated (reason 0x2a)
I: 50910[DL] Current number of connections: 0/1
D: 50914[DL] In DriveBLEState
I: 50917[DL] Setup PIN discriminator not found; using default: 07b

uart:~$ %                                                                                                                                                                         

[gjc13]

And here is the full packet capture:

nrfconnect_capture.pcapng.zip

[LuDuda]

Thank you @gjc13 for raising this issue.

Short description:

Based on the HCI Error (0x2a - BT_HCI_ERR_DIFF_TRANS_COLLISION) and attached pcap file, It seems that your BLE Central implementation violates Bluetooth specification, which results in expected BLE Disconnection from nRF side.

I did create a PR (#3916) which most likely hides this particular problem for the time being (by disabling BLE 2Mbps mode).
Please let me know if this unblocks you and if you can verify the issue on your side?

Long description:

Above I attached image which may help to understand the problem. Master is your BLE implementation and Slave is our nRF52840.
I have added two additional columns: Event counter and Instant which are essential.

Let me first quote the Bluetooth v5.2 Core, Vol 6. Low Energy Controller, Part B: Link Layer Specification, Section 5.3. Procedure Collisions.

Since LL Control PDUs are not interpreted in real time, collisions can occur
where the Link Layer of the master and the Link Layer of the slave initiate
incompatible procedures. Two procedures are incompatible if they both involve
an instant. In this situation, the rules in this section shall be followed:
A device shall not initiate a procedure after responding to a PDU that had
initiated an incompatible procedure until that procedure is complete.

If device initiates a procedure A and, while that procedure is not complete,
receives a PDU from its peer that initiates an incompatible procedure B, then:
• If the peer has already sent at least one PDU as part of procedure A, the
device should immediately exit the Connection State and transition to the
Standby State.
[..]

The Host shall be notified that the link has been disconnected with, or the
rejection PDU shall use (as appropriate):

• the error code LMP Error Transaction Collision / LL Procedure Collision
  (0x23) if procedures A and B are the same procedure;
• the error code LMP Error Transaction Collision / LL Procedure Collision
  (0x23) if procedure A is the Connection Update Procedure and procedure B
  is the Connection Parameters Request Procedure;
• the error code Different Transaction Collision (0x2A) otherwise.

If you look at the packets:

• the nRF52 initiates the LL_PHY_REQ in order to change the PHY to 2Mbps
• the BLE Central replies with LL_PHY_UPDATE_IND and sets the Instant to 14 (the event in which the change needs to be done)
• in the event number 8 (before 14) BLE Central initiates another procedure with an Instant LL_CONNECTION_UPDATE_REQ

This problem didn't occur on nRF5 SDK platform since the LL_PHY_REQ was not initiated by nRF (code only enabled 1Mbps that time).