L2CAP socket fail to open if pairing/bonding is enabled

[Allan P]

Environment

- MCU: nRF52832 (custom board)
- SDK: nRF Connect SDK v3.2.2

Problem Summary

Our nRF52832 firmware implements OTS (Object Transfer Service) with L2CAP for file transfer. 
The L2CAP server registers successfully and exposes its PSM via a GATT characteristic. However, the Android app fail to open the L2CAP socket.
BLE connection, pairing, bonding, and GATT operations all work correctly. Only the L2CAP CoC channel is never opened.

L2CAP was working fine without the pairing enabled.

Firmware Configuration

prj.conf (relevant excerpts) :
CONFIG_BT_SMP=y
CONFIG_BT_BONDABLE=y
CONFIG_BT_SMP_ENFORCE_MITM=n
CONFIG_BT_SMP_SC_PAIR_ONLY=n

CONFIG_BT_L2CAP_DYNAMIC_CHANNEL=y
CONFIG_BT_L2CAP_LOG_LEVEL_DBG=y

CONFIG_OTS_L2CAP=y
CONFIG_OTS_L2CAP_LE_PSM=37
CONFIG_OTS_L2CAP_SDU_MAX=264
CONFIG_OTS_L2CAP_SEC_LEVEL=1


The security level 2 is forced after connection width : 
bt_conn_set_security(conn, BT_SECURITY_L2);

OTS GATT Service Structure

The OTS service is defined with `BT_GATT_SERVICE_DEFINE` and includes:
- OTS Feature (Read, encrypted)
- Object Name (Read/Write, encrypted)
- Object Type, Size, First Created, Last Modified, Object ID, Properties (Read, encrypted)
- L2CAP PSM characteristic (Read, encrypted) -- returns PSM=37 as uint16 LE
- OACP (Write + Indicate, encrypted)
- OLCP (Write + Indicate, encrypted)
- Object List Filter (Write, encrypted)
- Object Changed (Indicate, encrypted)

I'm adding some logs : 

[00:01:08.767,913] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 5
[00:01:08.767,944] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x2000a108 len 5
[00:01:08.768,005] <dbg> bt_l2cap: bt_l2cap_send_pdu: push: pdu 0x2000e76c len 1 cb 0 userdata 0
[00:01:08.768,066] <dbg> bt_l2cap: raise_data_ready: L2CAP channel 0x2000a108 data ready added
[00:01:08.768,127] <dbg> bt_l2cap: get_ready_chan: sending from chan 0x2000a108 (static) data 1
[00:01:08.768,157] <dbg> bt_l2cap: l2cap_data_pull: Adding L2CAP PDU header: buf 0x2000e76c chan 0x2000a108 len 1 / 1
[00:01:08.768,188] <dbg> bt_l2cap: l2cap_data_pull: PDU payload
                                   13                                               |.                
[00:01:08.768,188] <dbg> bt_l2cap: l2cap_data_pull: last frag of last seg, dequeuing 0x2000e76c
[00:01:08.768,218] <dbg> bt_l2cap: l2cap_data_pull: done sending PDU
[00:01:08.768,218] <dbg> bt_l2cap: l2cap_data_pull: chan 0x2000a108 done
[00:01:08.768,249] <dbg> bt_l2cap: lower_data_ready: 0x2000a108
[00:01:08.768,310] <dbg> bt_l2cap: get_ready_chan: nothing to send on this conn
[00:01:08.768,341] <dbg> bt_l2cap: l2cap_data_pull: no channel conn 0x20003948
[00:01:08.828,033] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 10
[00:01:08.828,063] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x2000a108 len 10
[00:01:08.828,155] <dbg> bt_l2cap: bt_l2cap_send_pdu: push: pdu 0x2000e76c len 1 cb 0 userdata 0
[00:01:08.828,186] <dbg> bt_l2cap: raise_data_ready: L2CAP channel 0x2000a108 data ready added
[00:01:08.828,277] <dbg> bt_l2cap: get_ready_chan: sending from chan 0x2000a108 (static) data 1
[00:01:08.828,277] <dbg> bt_l2cap: l2cap_data_pull: Adding L2CAP PDU header: buf 0x2000e76c chan 0x2000a108 len 1 / 1
[00:01:08.828,308] <dbg> bt_l2cap: l2cap_data_pull: PDU payload
                                   13                                               |.                
[00:01:08.828,308] <dbg> bt_l2cap: l2cap_data_pull: last frag of last seg, dequeuing 0x2000e76c
[00:01:08.828,338] <dbg> bt_l2cap: l2cap_data_pull: done sending PDU
[00:01:08.828,338] <dbg> bt_l2cap: l2cap_data_pull: chan 0x2000a108 done
[00:01:08.828,369] <dbg> bt_l2cap: lower_data_ready: 0x2000a108
[00:01:08.828,460] <dbg> bt_l2cap: get_ready_chan: nothing to send on this conn
[00:01:08.828,460] <dbg> bt_l2cap: l2cap_data_pull: no channel conn 0x20003948
[00:01:08.884,582] <dbg> bt_l2cap: bt_l2cap_send_pdu: push: pdu 0x2000e76c len 6 cb 0 userdata 0
[00:01:08.884,643] <dbg> bt_l2cap: raise_data_ready: L2CAP channel 0x2000a108 data ready added
[00:01:08.884,704] <dbg> bt_l2cap: get_ready_chan: sending from chan 0x2000a108 (static) data 1
[00:01:08.884,704] <dbg> bt_l2cap: l2cap_data_pull: Adding L2CAP PDU header: buf 0x2000e76c chan 0x2000a108 len 6 / 6
[00:01:08.884,735] <dbg> bt_l2cap: l2cap_data_pull: PDU payload
                                   1d 30 00 70 05 01                                |.0.p..           
[00:01:08.884,765] <dbg> bt_l2cap: l2cap_data_pull: last frag of last seg, dequeuing 0x2000e76c
[00:01:08.884,765] <dbg> bt_l2cap: l2cap_data_pull: done sending PDU
[00:01:08.884,796] <dbg> bt_l2cap: l2cap_data_pull: chan 0x2000a108 done
[00:01:08.884,796] <dbg> bt_l2cap: lower_data_ready: 0x2000a108
[00:01:08.884,887] <dbg> bt_l2cap: get_ready_chan: nothing to send on this conn
[00:01:08.884,918] <dbg> bt_l2cap: l2cap_data_pull: no channel conn 0x20003948
[00:01:09.158,081] <inf> ble: Security level: 2
[00:01:09.217,895] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 1
[00:01:09.217,926] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x2000a108 len 1
[00:01:09.247,924] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 5
[00:01:09.247,955] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x2000a108 len 5
[00:01:09.248,016] <dbg> bt_l2cap: bt_l2cap_send_pdu: push: pdu 0x2000e76c len 1 cb 0 userdata 0
[00:01:09.248,077] <dbg> bt_l2cap: raise_data_ready: L2CAP channel 0x2000a108 data ready added
[00:01:09.248,138] <dbg> bt_l2cap: get_ready_chan: sending from chan 0x2000a108 (static) data 1
[00:01:09.248,168] <dbg> bt_l2cap: l2cap_data_pull: Adding L2CAP PDU header: buf 0x2000e76c chan 0x2000a108 len 1 / 1
[00:01:09.248,168] <dbg> bt_l2cap: l2cap_data_pull: PDU payload
                                   13                                               |.                
[00:01:09.248,199] <dbg> bt_l2cap: l2cap_data_pull: last frag of last seg, dequeuing 0x2000e76c
[00:01:09.248,229] <dbg> bt_l2cap: l2cap_data_pull: done sending PDU
[00:01:09.248,229] <dbg> bt_l2cap: l2cap_data_pull: chan 0x2000a108 done
[00:01:09.248,229] <dbg> bt_l2cap: lower_data_ready: 0x2000a108
[00:01:09.248,321] <dbg> bt_l2cap: get_ready_chan: nothing to send on this conn
[00:01:09.248,352] <dbg> bt_l2cap: l2cap_data_pull: no channel conn 0x20003948
[00:07:35.206,634] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 5
[00:07:35.206,665] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x2000a108 len 5
[00:07:35.206,726] <dbg> bt_l2cap: bt_l2cap_send_pdu: push: pdu 0x2000e76c len 1 cb 0 userdata 0
[00:07:35.206,787] <dbg> bt_l2cap: raise_data_ready: L2CAP channel 0x2000a108 data ready added
[00:07:35.206,848] <dbg> bt_l2cap: get_ready_chan: sending from chan 0x2000a108 (static) data 1
[00:07:35.206,878] <dbg> bt_l2cap: l2cap_data_pull: Adding L2CAP PDU header: buf 0x2000e76c chan 0x2000a108 len 1 / 1
[00:07:35.206,909] <dbg> bt_l2cap: l2cap_data_pull: PDU payload
                                   13                                               |.                
[00:07:35.206,909] <dbg> bt_l2cap: l2cap_data_pull: last frag of last seg, dequeuing 0x2000e76c
[00:07:35.206,939] <dbg> bt_l2cap: l2cap_data_pull: done sending PDU
[00:07:35.206,939] <dbg> bt_l2cap: l2cap_data_pull: chan 0x2000a108 done
[00:07:35.206,970] <dbg> bt_l2cap: lower_data_ready: 0x2000a108
[00:07:35.207,031] <dbg> bt_l2cap: get_ready_chan: nothing to send on this conn
[00:07:35.207,061] <dbg> bt_l2cap: l2cap_data_pull: no channel conn 0x20003948
[00:07:35.266,357] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 10
[00:07:35.266,387] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x2000a108 len 10
[00:07:35.266,479] <dbg> bt_l2cap: bt_l2cap_send_pdu: push: pdu 0x2000e76c len 1 cb 0 userdata 0
[00:07:35.266,510] <dbg> bt_l2cap: raise_data_ready: L2CAP channel 0x2000a108 data ready added
[00:07:35.266,601] <dbg> bt_l2cap: get_ready_chan: sending from chan 0x2000a108 (static) data 1
[00:07:35.266,601] <dbg> bt_l2cap: l2cap_data_pull: Adding L2CAP PDU header: buf 0x2000e76c chan 0x2000a108 len 1 / 1
[00:07:35.266,632] <dbg> bt_l2cap: l2cap_data_pull: PDU payload
                                   13                                               |.                
[00:07:35.266,662] <dbg> bt_l2cap: l2cap_data_pull: last frag of last seg, dequeuing 0x2000e76c
[00:07:35.266,662] <dbg> bt_l2cap: l2cap_data_pull: done sending PDU
[00:07:35.266,662] <dbg> bt_l2cap: l2cap_data_pull: chan 0x2000a108 done
[00:07:35.266,693] <dbg> bt_l2cap: lower_data_ready: 0x2000a108
[00:07:35.266,784] <dbg> bt_l2cap: get_ready_chan: nothing to send on this conn
[00:07:35.266,784] <dbg> bt_l2cap: l2cap_data_pull: no channel conn 0x20003948
[00:07:35.326,995] <dbg> bt_l2cap: bt_l2cap_send_pdu: push: pdu 0x2000e76c len 6 cb 0 userdata 0
[00:07:35.327,056] <dbg> bt_l2cap: raise_data_ready: L2CAP channel 0x2000a108 data ready added
[00:07:35.327,117] <dbg> bt_l2cap: get_ready_chan: sending from chan 0x2000a108 (static) data 1
[00:07:35.327,148] <dbg> bt_l2cap: l2cap_data_pull: Adding L2CAP PDU header: buf 0x2000e76c chan 0x2000a108 len 6 / 6
[00:07:35.327,148] <dbg> bt_l2cap: l2cap_data_pull: PDU payload
                                   1d 30 00 70 05 01                                |.0.p..           
[00:07:35.327,178] <dbg> bt_l2cap: l2cap_data_pull: last frag of last seg, dequeuing 0x2000e76c
[00:07:35.327,178] <dbg> bt_l2cap: l2cap_data_pull: done sending PDU
[00:07:35.327,209] <dbg> bt_l2cap: l2cap_data_pull: chan 0x2000a108 done
[00:07:35.327,209] <dbg> bt_l2cap: lower_data_ready: 0x2000a108
[00:07:35.327,301] <dbg> bt_l2cap: get_ready_chan: nothing to send on this conn
[00:07:35.327,331] <dbg> bt_l2cap: l2cap_data_pull: no channel conn 0x20003948
[00:07:35.386,230] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 1
[00:07:35.386,260] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x2000a108 len 1
[00:07:35.386,657] <dbg> bt_l2cap: bt_l2cap_recv: Packet for CID 4 len 5
[00:07:35.386,779] <dbg> bt_l2cap: l2cap_chan_recv: chan 0x2000a108 len 5
[00:07:35.386,840] <dbg> bt_l2cap: bt_l2cap_send_pdu: push: pdu 0x2000e76c len 1 cb 0 userdata 0
[00:07:35.386,901] <dbg> bt_l2cap: raise_data_ready: L2CAP channel 0x2000a108 data ready added
[00:07:35.386,962] <dbg> bt_l2cap: get_ready_chan: sending from chan 0x2000a108 (static) data 1
[00:07:35.386,993] <dbg> bt_l2cap: l2cap_data_pull: Adding L2CAP PDU header: buf 0x2000e76c chan 0x2000a108 len 1 / 1
[00:07:35.387,023] <dbg> bt_l2cap: l2cap_data_pull: PDU payload
                                   13                                               |.                
[00:07:35.387,023] <dbg> bt_l2cap: l2cap_data_pull: last frag of last seg, dequeuing 0x2000e76c
[00:07:35.387,054] <dbg> bt_l2cap: l2cap_data_pull: done sending PDU
[00:07:35.387,054] <dbg> bt_l2cap: l2cap_data_pull: chan 0x2000a108 done
[00:07:35.387,084] <dbg> bt_l2cap: lower_data_ready: 0x2000a108
[00:07:35.387,145] <dbg> bt_l2cap: get_ready_chan: nothing to send on this conn
[00:07:35.387,176] <dbg> bt_l2cap: l2cap_data_pull: no channel conn 0x20003948

I also tried with python on a PC and a raspberry, working good. I don't know how to debug this more. I don't see the problem.

Not much log on Android side (I'm not the one who work on the mobile app). The only said that the socket is NULL, so the creation failed. If needed I can ask for more but it may be a "black box" on their side.

Thanks.

[Einar Thorsrud]

Hi,

It seems like the problem is on the Android side, and that is where the focus should be. I am not an Android developer, but have some questions:

1. It would be interesting to know if the app implementation is calling Are they calling createL2capChannel(37) or createInsecureL2capChannel(37)?
2. Do you see this on all Android devices and Android versions or just some specific? If only some, which have tested and which fail?
3. Which exception or error do you get from the socket creation or call to connect()?

[Allan P]

Thanks for the reply, I just got it working.
In fact, Android was expecting level 3 with MITM.

The bug was, in fact, a communication issue between teams.