nrf5340 audio Unicast client/Gatt Client resubscribing to bonded peer characteristics

[adunk]

I have 2 nrf5340 devices, one running the Unicast Client and one running the Unicast Server. On the initial connection I am able to successfully stream audio.

On a restart of the Unicast server, the client successfully detects a BLE disconnection and I start scanning again. When the server restarts, I restart advertising to the bonded peer and the connection is successful but it appears the unicast client doesn't successfully resubscribe to the characteristic.

I have the CONFIG_BT_GATT_AUTO_RESUBSCRIBE set to y in the prj.conf but I don't see it happening in the drivers.

I get a warning on the server that :

HL [00:00:03.964,385] <wrn> bt_gatt: Device is not subscribed to characteristic
HL [00:00:03.964,385] <wrn> bt_pacs: PACS notify failed: -22

On the client side it shows issues initially by the "More than one sink endpoing..." warning. But then it appears to configure the sink connection:
-- [00:00:38.572,692] <dbg> unicast_client: available_contexts_cb: conn: D1:3A:F6:65:C0:9C (random), snk ctx 5 src ctx 0
-- [00:00:39.972,564] <dbg> unicast_client: available_contexts_cb: conn: D1:3A:F6:65:C0:9C (random), snk ctx 5 src ctx 0
-- [00:00:40.172,576] <wrn> unicast_client: More than one sink endpoint found, idx 0 is used by default
-- [00:00:40.972,503] <dbg> unicast_client: supported_sample_rates_print: Headset supports: 48, 24, 16, kHz in sink direction
-- [00:00:41.073,944] <inf> unicast_client: LEFT sink stream configured
-- [00:00:41.073,974] <dbg> unicast_client: stream_configured_cb: Configured Stream info: LEFT, 0x20002818, dir 1
-- [00:00:41.073,974] <dbg> unicast_client: headset_pres_delay_find: Index: 0, Pref min: 10000, pref max: 40000, pres_min: 4000, pres_max: 60000
-- [00:00:41.074,005] <dbg> unicast_client: stream_configured_cb: Set LEFT headset, connection 0x20002a08, stream 0x20002818

But then I get no audio streaming. 

Is there anything else that needs to be done to have the Unicast Client automatically resubscribe to the server?

[adunk]

Update...I did find I needed to do a little more cleanup on the disconnection when the server was reset and now my client side is configuring immediately on the connection. But I still do not get the audio streaming and I still get the bt_gatt and bt_pacs warnings which indicate I am still not properly subscribing to the characteristic properly on a restart.

[AHaug]

Hi,

I've picked up your case and will be looking into your issue. Do you know if the issue is reproducable on an Audio DK? Could you verify if "Unicast client and server" corresponds to "audio application gateway and headset", or are you using the unicast_audio_client-/server from Zephyr?

Could you also state what SDK and version you're working with?

Kind regards,
Andreas

[adunk]

I am using nrf Connect 2.6.1.

When trying to duplicate the issue on the nRF Audio demo...

On the client side, I don't get the "more than one sink endpoint found" warning.  So something must be going on with the timing of the service discovery.  It later successfully finds the LEFT sink, but apparently the initial incorrect configuration is enough to affect the streaming. 

GW [00:20:43.568,298] <inf> bt_mgmt_scan: Local addr: 74:60:22:FC:EF:24 (random). May time out. Updates not printed
GW [00:20:43.568,298] <inf> bt_mgmt_scan: Scanning successfully started
GW [00:20:43.576,385] <inf> bt_mgmt_scan: Creating connection to bonded device: DB:CB:13:0F:2B:1A (random)
GW [00:20:43.581,146] <inf> bt_mgmt: Connected: DB:CB:13:0F:2B:1A (random)
GW [00:20:43.582,366] <inf> bt_mgmt_scan: Local addr: 74:60:22:FC:EF:24 (random). May time out. Updates not printed
GW [00:20:43.582,366] <inf> bt_mgmt_scan: Scanning successfully started
GW [00:20:43.582,397] <inf> main: Device connected
GW [00:20:43.861,724] <inf> main: Security changed
GW [00:20:44.742,004] <inf> bt_rend_vol: VCS discover finished
GW [00:20:46.343,078] <inf> unicast_client: LEFT sink stream configured
GW [00:20:46.422,393] <inf> unicast_client: Enable stream 0x20002c90
GW [00:20:46.741,607] <inf> unicast_client: Stream 0x20002c90 started
GW [00:20:46.742,919] <inf> audio_usb: USB RX first data received.

On the server side, I get the same warning when resetting the Headset but the audio starts streaming and I can hear it over the headphones. I thought that warning was the issue since I am not getting any audio but apparently it recovers from this issue and at some point subscribes to the audio notifications.

nRF5340 Audio nRF5340 Audio DK cpuapp
NCS base version: 2.6.1
Cmake run : Tue May 28 06:46:07 2024
HL [00:00:00.323,608] <inf> fw_info: ------- DEBUG BUILD -------
HL [00:00:00.323,608] <inf> fw_info: HEADSET left device
HL [00:00:00.343,414] <inf> bt_mgmt_ctlr_cfg: Controller: SoftDevice: Version 5.4 (0x0d), Revision 8591
HL [00:00:00.343,627] <inf> bt_mgmt: Local identity addr: DB:CB:13:0F:2B:1A (random)
HL [00:00:00.348,968] <inf> bt_mgmt_adv: Local addr: 5B:93:B0:E7:9A:1B (random)
HL [00:00:00.349,060] <inf> bt_mgmt_adv: Adv directed to: DB:41:76:83:AD:E1 (random).
HL [00:00:00.349,670] <inf> bt_mgmt_adv: Advertising successfully started
HL [00:00:00.576,354] <inf> bt_mgmt: Connected: DB:41:76:83:AD:E1 (random)
HL [00:00:00.576,385] <inf> main: Connected
HL [00:00:00.576,965] <inf> bt_mgmt_adv: RPA (Resolvable Private Address) expired.
HL [00:00:00.577,056] <inf> bt_mgmt_adv: Local addr: 5B:93:B0:E7:9A:1B (random)
HL [00:00:00.857,116] <inf> main: Security changed
HL [00:00:00.857,391] <wrn> bt_gatt: Device is not subscribed to characteristic
HL [00:00:00.857,391] <wrn> bt_pacs: PACS notify failed: -22
HL [00:00:02.817,718] <inf> bt_content_ctrl_media: Discovery of MCS finished
HL [00:00:03.137,725] <inf> unicast_server: LC3 codec config for sink:
HL [00:00:03.137,725] <inf> unicast_server: Frequency: 48000 Hz
HL [00:00:03.137,725] <inf> unicast_server: Duration: 10000 us
HL [00:00:03.137,725] <inf> unicast_server: Channel allocation: 0x1
HL [00:00:03.137,756] <inf> unicast_server: Octets per frame: 120 (96000 bps)
HL [00:00:03.137,756] <inf> unicast_server: Frames per SDU: 1
HL [00:00:03.217,651] <inf> main: Presentation delay 10000 us is set by initiator
HL [00:00:03.544,158] <inf> unicast_server: Stream 0x2000fec8 started
HL [00:00:03.556,915] <wrn> audio_datapath: Data received, total under-runs: 1
HL [00:00:03.593,933] <inf> audio_datapath: Drft comp state: CALIB
HL [00:00:03.693,939] <inf> audio_datapath: Drft comp state: OFFSET
HL [00:00:04.193,664] <inf> audio_datapath: Drft comp state: LOCKED
HL [00:00:04.193,939] <inf> audio_datapath: Pres comp state: MEAS
HL [00:00:04.303,955] <inf> audio_datapath: Pres comp state: WAIT
HL [00:00:04.443,939] <inf> audio_datapath: Pres comp state: INIT
HL [00:00:04.453,948] <inf> audio_datapath: Pres comp state: MEAS
HL [00:00:04.563,934] <inf> audio_datapath: Pres comp state: LOCKED

I'll try to look into why this mechanism is failing initially, but any insight into how the initial discovery is failing would be very helpful.

[AHaug]

Hi,

HL [00:00:00.857,391] <wrn> bt_pacs: PACS notify failed: -22

The failure seems to be caused by an invalid argument, and the notify fails due to the peer not having enabled notification in this characteristic. Did you state that this error only occurs sometimes? When we try to recreate and set up the nRF audio application gateway and headset we're not able to see the same behavior on our end.. 

The PACS should describe what configs and features the device should support and I assume that your peripheral supports notifications. Are you able to verify this and narrow down any further why this occurs? It seems possible that it could be a following error due to the PACS notification failure

Kind regards,
Andreas

[adunk]

Thank you for trying to duplicate this. I am also not seeing this issue on the dev kit with the example although I tried to leverage that for my development. I must have missed something. I will look into this and report back. Please give me a few days as I have other pressing issues and we have a temporary work-around for this current issue.

[AHaug]

Noted, no worries about the time you need. I was unfortunately a bit busy myself the past week!.. The case will be left open until it's closed by you or we mark it as resolved and it will pop into my queue as soon as you reply (or bounce back to a team-queue if I'm out of office for a few days when you get back to me).

Kind regards,
Andreas