Specific Android tablet model isn't able to reliably connect

[FlsZen]

I have a fairly simple application running on an nRF52832 exposing a few services over Bluetooth LE. I received a report of a Lenovo M10 (TB328FU) that was unable to connect. I imported one to test with and was able to reproduce the issue, even with the tablet fully patched. I haven't seen this issue with any other Android or iOS devices. As a (hopefully temporary) workaround, I disabled the 2 Mbps PHY which avoids the issue and the M10 can then connect and communicate successfully.

I found that the nRF is reporting an error when the M10 tries to change the PHY from 1 Mbps to 2 Mbps during the connection. Based on the error, I assume it is coming from the SoftDevice, but I'm new to this and don't understand exactly what is going on or what I may be able to adjust to resolve it.

Here's what appears to me to be the problematic packet in the sniffer (full sniffer pcap also attached of to M10 failing to connect). The Expert error is "Initiating a new incompatible control procedure after having sent a response to an incompatible control procedure"

In the nRF's log I see the following line right before disconnection:

bt_hci_core: hci_disconn_complete: status 0x00 handle 0 reason 0x2a

I'm not sure what reason 2a implies, but traced it to a name "BT_HCI_ERR_DIFF_TRANS_COLLISION".

Thanks for looking and I appreciate any guidance you can offer!

M10 not connecting.pcapng

Fullscreen BT log didn't connect.txt Download

[00:00:19.141,296] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001ed8 to poll list
[00:00:19.141,326] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:19.141,326] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:19.141,387] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20007b74 opcode 0x2016 len 0
[00:00:19.141,418] <dbg> bt_hci_core: bt_hci_cmd_create: opcode 0x2032 param_len 7
[00:00:19.141,448] <dbg> bt_hci_core: bt_hci_cmd_create: buf 0x20007b74
[00:00:19.141,479] <dbg> bt_hci_core: bt_hci_cmd_send_sync: buf 0x20007b74 opcode 0x2032 len 10
[00:00:19.141,510] <dbg> bt_hci_core: process_events: count 3
[00:00:19.141,540] <dbg> bt_hci_core: process_events: ev->state 4
[00:00:19.141,571] <dbg> bt_hci_core: send_cmd: calling net_buf_get
[00:00:19.141,571] <dbg> bt_hci_core: send_cmd: calling sem_take_wait
[00:00:19.141,601] <dbg> bt_hci_core: send_cmd: Sending command 0x2032 (buf 0x20007b74) to driver
[00:00:19.141,632] <dbg> bt_hci_core: bt_send: buf 0x20007b74 len 10 type 0
[00:00:19.141,662] <dbg> bt_sdc_hci_driver: hci_driver_send: 
[00:00:19.141,662] <dbg> bt_sdc_hci_driver: cmd_handle: 
[00:00:19.141,723] <dbg> bt_sdc_hci_driver: hci_driver_send: Exit: 0
[00:00:19.141,754] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:19.141,784] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:19.141,815] <dbg> bt_sdc_hci_driver: event_packet_process: Command Status (0x2032) status: 0x00
[00:00:19.141,845] <dbg> bt_hci_core: bt_recv: buf 0x20007b74 len 6
[00:00:19.141,876] <dbg> bt_hci_core: hci_cmd_status: opcode 0x2032
[00:00:19.141,876] <dbg> bt_hci_core: hci_cmd_done: opcode 0x2032 status 0x00 buf 0x20007b74
[00:00:19.141,967] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:19.141,998] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20001ed8 to poll list
[00:00:19.141,998] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:19.142,028] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 3 events
[00:00:19.142,089] <dbg> bt_hci_core: bt_hci_cmd_send_sync: rsp 0x20007b74 opcode 0x2032 len 0
[00:00:19.142,120] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
[00:00:19.266,235] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x04), len (12)
[00:00:19.266,265] <dbg> bt_hci_core: bt_recv: buf 0x20007890 len 14
[00:00:19.266,357] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:19.266,357] <dbg> bt_hci_core: rx_work_handler: buf 0x20007890 type 1 len 14
[00:00:19.266,387] <dbg> bt_hci_core: hci_event: event 0x3e
[00:00:19.266,387] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x04
[00:00:19.266,418] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
[00:00:19.266,448] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
[00:00:19.536,132] <dbg> bt_sdc_hci_driver: event_packet_process: LE Meta Event (0x07), len (11)
[00:00:19.536,163] <dbg> bt_hci_core: bt_recv: buf 0x20007890 len 13
[00:00:19.536,224] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:19.536,254] <dbg> bt_hci_core: rx_work_handler: buf 0x20007890 type 1 len 13
[00:00:19.536,285] <dbg> bt_hci_core: hci_event: event 0x3e
[00:00:19.536,285] <dbg> bt_hci_core: hci_le_meta_event: subevent 0x07
[00:00:19.536,315] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
[00:00:19.536,346] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
[00:00:19.806,243] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
--- 3 messages dropped ---
[00:00:19.806,274] <dbg> bt_conn: bt_conn_set_state: connected -> disconnect-complete
[00:00:19.806,304] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
[00:00:19.806,365] <dbg> bt_hci_core: rx_work_handler: Getting net_buf from queue
[00:00:19.806,396] <dbg> bt_hci_core: rx_work_handler: buf 0x20007890 type 1 len 6
[00:00:19.806,427] <dbg> bt_hci_core: hci_event: event 0x05
[00:00:19.806,427] <dbg> bt_hci_core: hci_disconn_complete: status 0x00 handle 0 reason 0x2a
[00:00:19.806,457] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
[00:00:19.806,518] <dbg> bt_conn: bt_conn_set_state: disconnect-complete -> disconnected
[00:00:19.806,518] <dbg> bt_conn: tx_notify: conn 0x20001ed8
[00:00:19.806,549] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
[00:00:19.806,610] <dbg> bt_hci_core: process_events: count 3
[00:00:19.806,610] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:19.806,640] <dbg> bt_hci_core: process_events: ev->state 1
[00:00:19.806,640] <dbg> bt_hci_core: process_events: ev->state 0
[00:00:19.806,671] <dbg> bt_conn: bt_conn_prepare_events: 
[00:00:19.806,701] <dbg> bt_hci_core: hci_tx_thread: Calling k_poll with 2 events
[00:00:19.806,732] <dbg> bt_conn: deferred_work: conn 0x20001ed8
[00:00:19.806,762] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x20001ed8 chan 0x20003b5c
[00:00:19.806,762] <dbg> bt_l2cap: l2cap_disconnected: ch 0x20003b5c cid 0x0005
[00:00:19.806,793] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x20001ed8 chan 0x20003cf0
[00:00:19.806,823] <dbg> bt_l2cap: bt_l2cap_chan_del: conn 0x20001ed8 chan 0x2000585c
[00:00:19.806,823] <dbg> bt_att: bt_att_disconnected: chan 0x2000585c cid 0x0004
[00:00:19.806,854] <dbg> bt_att: att_chan_detach: chan 0x20005858
[00:00:19.806,884] <dbg> bt_gatt: bt_gatt_disconnected: conn 0x20001ed8
[00:00:19.806,976] <dbg> bt_att: bt_att_released: chan 0x20005858
[00:00:19.807,006] <dbg> bt_conn: bt_conn_unref: handle 0 ref 1 -> 0

2816.prj.conf

[Hung Bui]

Hi James, 

Reason 0x2A = DIFFERENT_TRANSACTION_COLLISION. This can happen when the central send a PHY update and connection parameter update next to each other (collision). 
The PHY update actually requested by the nR52. My suggestion is to try putting a delay in the request in the code so that it doesn't happen at the same time as with the connection parameter update from the central. 

[FlsZen]

Hi,

I don't believe I'm calling any code that would initiate a PHY update from my code on the nRF52, is there something that would be on by default that I may need to turn off?

To eliminate variables from my concern here, I have built and flashed the peripheral_lbs sample to my nRF52-DK. My other devices connect and interact fine with the sample app, but this M10 tablet continues to time out in the same place while connecting. The nRF Connect log is identical in that it disconnects just under 5 seconds after logging "PHY updated (TX: LE 2M, RX: LE 2M)". I can provide logs from the running peripheral_lbs sample code if needed.

[Hung Bui]

Hi James, 

It's most likely because of the CONFIG_BT_AUTO_PHY_UPDATE. It's by default =y. 
You can turn it off if you don't plan to let the peripheral to request PHY update. 
If you want the peripheral to request PHY update but have more control over it, you can use CONFIG_BT_USER_PHY_UPDATE=y then call bt_conn_le_phy_update() in your application. 
Please let us know if this doesn't fix the problem for you. 

[FlsZen]

Thanks! Setting `CONFIG_BT_AUTO_PHY_UPDATE=n` resolves the issue when this M10 is connecting to it and I can now re-enable the 2Mbps PHY option which was my previous workaround.