Intermittent BLE connection

[adunk]

I am working with nRF Connect SDK 2.6.1 on a Central and a Peripheral and I am running the BAP similar to the nRF Audio Example. I am using out of band pairing over UART for the initial secure connection. The OOB pairing works fine.

After connection is established and bonds are saved, the peripheral basically always advertises if bonds exist. The central device is turned on and off and scans when it turns on. I know this is a little different than traditionally, but the Basic Audio Profile forced which devices are the Central and the Peripheral.

If I continuously cycle power to the Central and watch the log output, quite frequently I can see that sometimes it needs multiple attempts to connect. It seems to happen more frequently when the area is a little more ACTIVE in the BLE band. 

I'm using Wireshark with the nRF Sniffer to look at the BLE traffic, and it seems like the Peripheral (Slave on the Wireshark log), stops responding to the Centrals (Master) packets. I'm using security level 4 so Wireshark is unable to decrypt the message, but I should still see a response from the Peripheral in order to maintain the connectivity.

It seems quite frequently the peripheral stops responding after it sends the OP Code LL_START_ENC_REQ.  Here's the log of the connection and when the peripheral stops responding.

Here is a successful connection where you can see constant communication between the central and the peripheral:

On my log output on the Central and the Peripheral when the failure occurs I can see the connection occur but then a "Security failed" notification. It then seems to struggle with the disconnection but eventually does, it then starts advertising again and then successfully connects for the most part on the 2nd attempt. Sometimes it takes a couple of attempts but it seems to always reconnect.

-- [00:04:21.230,010] <dbg> event: thread_status_event_supv: Conn evnt
-- [00:04:21.580,444] <wrn> ble_supv: Security failed: level 1 err 9
-- [00:04:21.580,474] <wrn> ble_supv: Failed to disconnect -128
-- [00:04:21.580,718] <dbg> event: thread_status_event_supv: Disc Evnt
-- [00:04:21.640,258] <inf> ble_supv: Advertising to xx:xx:xx:xx:xx:xx (random) started

-- [00:04:25.829,498] <dbg> event: thread_status_event_supv: Conn evnt

I am wondering about the procedure when the Central device is powered down and disconnects. I'm basically just calling the functions to stop streaming and disconnect and then powering down. The peripheral does seem to take a couple of seconds to recognize the disconnection and receive the "disconnect" callback. But even if I ensure to wait for this callback on the peripheral to occur before turning the central back on, I still get the occasional failure. Is there still something hanging up in the peripheral device from the connection that is occuring due to my procedure for the disconnection? What should the procedure be to properly stop streaming and disconnect from a peripheral? Is it possible its somehow using the "conn" handle from the previous connection?

The current BLE disconnection procedure when the central is shut down. There is a little more error checking, but basically if we're streaming, stop the streaming and then disconnect:

if (!bt_content_ctlr_media_state_playing()){

        return 0; // we are already paused

    }

bt_content_ctrl_stop(default_conn);

bt_conn_disconnect(default_conn, BT_HCI_ERR_REMOTE_USER_TERM_CONN);

Its also possible the disconnection procedure has nothing to do with this failure. I'm using whitelisting on the peripheral so it only connects to the bonded device. But I am just using regular advertising rather than directed advertising. I didn't see the need for directed advertising since we're using out of band pairing. 

[Hieu]

Hi adunk,

After connection is established and bonds are saved, the peripheral basically always advertises if bonds exist. The central device is turned on and off and scans when it turns on. I know this is a little different than traditionally, but the Basic Audio Profile forced which devices are the Central and the Peripheral.

I am not familiar with what BAP requires here, but this sound pretty much the same as how a pair of Central and Peripheral would work since Bluetooth 4.x, no? Could I perhaps miss something here?

But if dwelling in the reasons of the setup is not directly related to the issue, we can skip this part.

I am wondering about the procedure when the Central device is powered down and disconnects. I'm basically just calling the functions to stop streaming and disconnect and then powering down. The peripheral does seem to take a couple of seconds to recognize the disconnection and receive the "disconnect" callback.

This sound like the Central powering down happen too quick that the call to disconnect didn't actually work on the Central yet. The Peripheral would then just keep waiting for Central packets that stop coming and eventually time out.

Since you already have a sniffer setup, can you check if that is the case? You could temporarily disable encryption just for this test too.

Also, how does this power cycle happen? Power cycle usually mean a physical power cut and restore. However, you mentioned the central ending the stream and disconnect, that sounds like software is involved.

Is there still something hanging up in the peripheral device from the connection that is occuring due to my procedure for the disconnection?

From what you have described here, that can seem to be the case, but there shouldn't be anything like that...

Let's also look at these logs:

-- [00:04:21.230,010] <dbg> event: thread_status_event_supv: Conn evnt
-- [00:04:21.580,444] <wrn> ble_supv: Security failed: level 1 err 9
-- [00:04:21.580,474] <wrn> ble_supv: Failed to disconnect -128
-- [00:04:21.580,718] <dbg> event: thread_status_event_supv: Disc Evnt
-- [00:04:21.640,258] <inf> ble_supv: Advertising to xx:xx:xx:xx:xx:xx (random) started

-- [00:04:25.829,498] <dbg> event: thread_status_event_supv: Conn evnt

I assume ble_supv is one of your code module, and the code is based on one of the sample code. In that case, "Failed to disconnect -128" comes from bt_conn_disconnect(), and error 128 means there wasn't a connection.

This is quite odd. The two modules of the Bluetooth stack involved here are SMP and CONN. Could you please enable these configs to get more logs?
CONFIG_BT_SMP_LOG_LEVEL_DBG
CONFIG_BT_CONN_LOG_LEVEL_DBG  

There could be a significant increase in amount of log, so you might also need to configure more buffers for the log module. Please also make sure CONFIG_LOG_MODE_DEFERRED is enabled to minimize the impact of logging to the Bluetooth stack's operations.

What should the procedure be to properly stop streaming and disconnect from a peripheral? Is it possible its somehow using the "conn" handle from the previous connection?

It would be best to wait for a callback confirming the success of an operation before moving on to the next step.

The current BLE disconnection procedure when the central is shut down. There is a little more error checking, but basically if we're streaming, stop the streaming and then disconnect:

if (!bt_content_ctlr_media_state_playing()){

        return 0; // we are already paused

    }

bt_content_ctrl_stop(default_conn);

bt_conn_disconnect(default_conn, BT_HCI_ERR_REMOTE_USER_TERM_CONN);

Its also possible the disconnection procedure has nothing to do with this failure.

Right, so this looks like there is no wait for any procedures to complete at all. Still, in an ideal world, the peripheral should be robust enough that it isn't impacted by what the central does.

I'm using whitelisting on the peripheral so it only connects to the bonded device. But I am just using regular advertising rather than directed advertising. I didn't see the need for directed advertising since we're using out of band pairing. 

Noted.

Hieu

[adunk]

Yes, ble_supv is the module where I receive the BLE callbacks. I then push an event into the event_supv and perform the functionality.

I turned the debug logging on the peripheral on those 2 modules and duplicated the failure process.  Here's the output from Wireshark during the failure:

Here's the debug output from the connection callback to a little after the disconnection occurs. You can see it restarting the advertising at the end of 9:06 and then reconnect at 9:11:
-- [00:09:06.095,275] <dbg> event: thread_status_event_supv: Bonds:Conn Evnt
-- [00:09:06.095,275] <dbg> event: thread_status_event_supv: No phy conn
-- [00:09:06.095,520] <dbg> bt_conn: bt_conn_unref: handle 137 ref 2 -> 1
-- [00:09:06.095,550] <dbg> bt_conn: bt_conn_ref: handle 137 ref 1 -> 2
-- [00:09:06.095,550] <dbg> bt_conn: bt_conn_unref: handle 137 ref 2 -> 1
-- [00:09:06.145,233] <dbg> bt_conn: bt_conn_ref: handle 137 ref 1 -> 2
-- [00:09:06.145,263] <dbg> bt_conn: tx_notify: conn 0x20004080
-- [00:09:06.145,263] <dbg> bt_conn: bt_conn_recv: handle 137 len 7 flags 02
-- [00:09:06.145,263] <dbg> bt_conn: bt_acl_recv: First, len 7 final 3
-- [00:09:06.145,263] <dbg> bt_conn: bt_acl_recv: Successfully parsed 7 byte L2CAP packet
-- [00:09:06.145,294] <dbg> bt_conn: bt_conn_send_cb: conn handle 137 buf len 7 cb 0x55d5d us er_data 0x20013314
-- [00:09:06.145,324] <dbg> bt_conn: bt_conn_ref: handle 137 ref 2 -> 3
-- [00:09:06.145,324] <dbg> bt_conn: bt_conn_unref: handle 137 ref 3 -> 2
-- [00:09:06.145,385] <dbg> bt_conn: bt_conn_unref: handle 137 ref 2 -> 1
-- [00:09:06.145,385] <dbg> bt_conn: bt_conn_process_tx: conn 0x20004080
-- [00:09:06.145,416] <dbg> bt_conn: send_buf: conn 0x20004080 buf 0x20024558 len 7
-- [00:09:06.145,416] <dbg> bt_conn: send_buf: send single
-- [00:09:06.145,416] <dbg> bt_conn: do_send_frag: conn 0x20004080 buf 0x20024558 len 7 flags 0x02
-- [00:09:06.145,446] <dbg> bt_conn: bt_conn_prepare_events:
-- [00:09:06.145,477] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004080 to poll list
-- [00:09:06.145,477] <dbg> bt_conn: conn_prepare_events: wait on host fifo
-- [00:09:06.195,648] <dbg> bt_conn: bt_conn_ref: handle 137 ref 1 -> 2
-- [00:09:06.195,648] <dbg> bt_conn: bt_conn_unref: handle 137 ref 2 -> 1
-- [00:09:06.245,330] <dbg> bt_conn: bt_conn_ref: handle 137 ref 1 -> 2
-- [00:09:06.245,361] <dbg> bt_conn: bt_conn_unref: handle 137 ref 2 -> 1
-- [00:09:06.245,391] <dbg> bt_conn: tx_complete_work: conn 0x20004080
-- [00:09:06.245,391] <dbg> bt_conn: tx_notify: conn 0x20004080
-- [00:09:06.245,391] <dbg> bt_conn: tx_notify: tx 0x20012e8c cb 0x55d5d user_data 0x20013314
-- [00:09:06.295,593] <dbg> bt_conn: bt_conn_ref: handle 137 ref 1 -> 2
-- [00:09:06.295,623] <dbg> bt_conn: bt_conn_unref: handle 137 ref 2 -> 1
-- [00:09:06.295,684] <dbg> bt_conn: bt_conn_prepare_events:
-- [00:09:06.295,684] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004080 to poll list
-- [00:09:06.295,715] <dbg> bt_conn: conn_prepare_events: wait on host fifo
-- [00:09:06.645,233] <dbg> bt_conn: bt_conn_ref: handle 137 ref 1 -> 2
-- [00:09:06.645,233] <dbg> bt_conn: bt_conn_set_state: connected -> disconnect-complete
-- [00:09:06.645,263] <dbg> bt_conn: bt_conn_unref: handle 137 ref 2 -> 1
-- [00:09:06.645,294] <dbg> bt_conn: bt_conn_ref: handle 137 ref 1 -> 2
-- [00:09:06.645,324] <dbg> bt_conn: bt_conn_set_state: disconnect-complete -> disconnected
-- [00:09:06.645,324] <dbg> bt_conn: tx_notify: conn 0x20004080
-- [00:09:06.645,324] <dbg> bt_conn: bt_conn_unref: handle 137 ref 2 -> 1
-- [00:09:06.645,385] <dbg> bt_conn: bt_conn_prepare_events:
-- [00:09:06.645,416] <dbg> bt_conn: deferred_work: conn 0x20004080
-- [00:09:06.645,416] <dbg> bt_smp: bt_smp_disconnected: chan 0x20004fdc cid 0x0006
-- [00:09:06.645,446] <dbg> bt_smp: smp_pairing_complete: got status 0x8
-- [00:09:06.645,446] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x20004fdc conn 0x20004080 ha ndle 137 encrypt 0x00 hci status 0x1f
-- [00:09:06.645,477] <wrn> ble_supv: Security failed: level 1 err 9
-- [00:09:06.645,477] <wrn> ble_supv: Failed to disconnect -128
-- [00:09:06.645,660] <dbg> bt_conn: bt_conn_unref: handle 137 ref 1 -> 0
-- [00:09:06.645,721] <dbg> event: thread_status_event_supv: Disc Evnt
-- [00:09:06.702,270] <dbg> bt_conn: bt_conn_prepare_events:
-- [00:09:06.702,606] <dbg> bt_conn: bt_conn_prepare_events:
-- [00:09:06.702,972] <dbg> bt_conn: bt_conn_prepare_events:
-- [00:09:06.703,369] <dbg> bt_conn: bt_conn_prepare_events:
-- [00:09:06.703,704] <dbg> bt_conn: bt_conn_prepare_events:
-- [00:09:06.704,101] <dbg> bt_conn: bt_conn_prepare_events:
-- [00:09:06.704,406] <dbg> bt_conn: bt_conn_set_state: disconnected -> connecting-adv
-- [00:09:06.704,437] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
-- [00:09:06.704,498] <dbg> bt_conn: bt_conn_prepare_events:
-- [00:09:06.704,925] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
-- [00:09:06.705,017] <inf> ble_supv: Advertising to D0:1F:FC:25:40:22 (random) started
-- [00:09:11.997,802] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
-- [00:09:11.997,833] <dbg> bt_conn: bt_conn_unref: handle 0 ref 2 -> 1
-- [00:09:11.997,833] <dbg> bt_conn: bt_conn_ref: handle 0 ref 1 -> 2
-- [00:09:11.997,863] <dbg> bt_conn: bt_conn_set_state: connecting-adv -> connected
-- [00:09:11.997,894] <dbg> bt_smp: bt_smp_accept: conn 0x20004080 handle 146
-- [00:09:11.997,894] <dbg> bt_smp: bt_smp_connected: chan 0x20004fdc cid 0x0006
-- [00:09:11.998,443] <dbg> bt_conn: bt_conn_prepare_events:
-- [00:09:11.998,474] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004080 to poll list
-- [00:09:11.998,474] <dbg> bt_conn: conn_prepare_events: wait on host fifo
-- [00:09:11.998,596] <dbg> event: thread_status_event_supv: Conn evnt
-- [00:09:11.998,596] <inf> oob: Push:20
-- [00:09:11.998,687] <dbg> event: thread_status_event_supv: Bonds:Conn Evnt
-- [00:09:11.998,687] <dbg> event: thread_status_event_supv: No phy conn
-- [00:09:11.998,931] <dbg> bt_conn: bt_conn_unref: handle 146 ref 2 -> 1
-- [00:09:11.998,962] <dbg> bt_conn: bt_conn_ref: handle 146 ref 1 -> 2
-- [00:09:11.998,962] <dbg> bt_conn: bt_conn_unref: handle 146 ref 2 -> 1
-- [00:09:12.199,035] <dbg> bt_conn: bt_conn_ref: handle 146 ref 1 -> 2
-- [00:09:12.199,096] <dbg> bt_conn: bt_conn_unref: handle 146 ref 2 -> 1
-- [00:09:12.199,127] <dbg> bt_conn: bt_conn_prepare_events:
-- [00:09:12.199,157] <dbg> bt_conn: conn_prepare_events: Adding conn 0x20004080 to poll list
-- [00:09:12.199,157] <dbg> bt_conn: conn_prepare_events: wait on host fifo
-- [00:09:12.498,992] <dbg> bt_conn: bt_conn_ref: handle 146 ref 1 -> 2
-- [00:09:12.498,992] <dbg> bt_smp: bt_smp_encrypt_change: chan 0x20004fdc conn 0x20004080 ha ndle 146 encrypt 0x01 hci status 0x00

I could also do the same for the Central. But its a little more challenging to get access to that debug UART. But I could if necessary to debug this issue.

As for the shutdown issue, we plan on fixing the shutdown procedure in the Central to wait for the disconnect callback so the peripheral doesn't need to timeout, but that doesn't seem to be the problem in this case because the peripheral is advertising and definitely not connected in this case.  Unless of course its not recovering properly.

[adunk]

As a reference, heres the log from a successful connection:

[adunk]

I was able to get a log file from the Central when the failure occurred as well.