• State Verified Answer
  • Replies 19 replies
  • Subscribers 76 subscribers
  • Views 4303 views
  • Users 0 members are here
Attachments (2) Download All
Nordic Case Info
  • Case ID: 302421
Options

LE Audio timeout behaviour (0x08) interfacing with third party devices.

kieran.cheung

Hi, I'm currently developing a device that acts as an LE Audio client. Everything works as expected when interfacing with an LE Audio server counterpart on a 5340 Audio DK, also using the Zephyr BLE Audio API.

However I recently attempted to interface my client with a third party pair of LE Audio headphones, specifically the Earfun Air Pro 3s, and upon enabling the streams (bt_audio_stream_enable) the device receives no response callback and supposedly hits the supervisory timeout (disconnect reason 0x08.) At first I suspected this may be an issue with the headphones, and I haven't ruled out this possibility.

But then I decided to test the nrF5340 audio application (unmodified) with the Android LE Audio framework in the developer settings, which seems to work decently well with the Earfun Air Pro 3s. I found that the 5340 headset application was successfully receiving and playing back the stream for 4s, but then receives a timeout event and immediately stops playing. 

There's a chance these are unrelated issues but seeing as they both involve supervision timeouts, there's the possibility something is not being handled correctly on the 5340? Can something about the LE Audio framework cause it to stop sending packets to the peer device? Has the audio application been tested with any third party devices?

I have tried changing the clock source with:

CONFIG_CLOCK_CONTROL_NRF_K32SRC_SYNTH=y
As I heard this has been related to other timeout issues, but that doesn't seem to be the cause here as it has no effect.

Log from headset:

HL [00:01:04.268,341] <inf> cis_headset: Connected: 0C:C4:13:2F:AD:44 (public)
HL [00:01:09.610,137] <inf> ble_audio_services: Volume = 10, mute state = 0
HL [00:08:10.497,955] <dbg> bt_audio_stream: bt_audio_stream_attach: conn 0x20002db8 stream 0x2000a728 ep 0x2000ba34 codec 0x2000ba44
HL [00:08:10.587,951] <dbg> bt_audio_stream: bt_audio_stream_iso_listen: stream 0x2000a728 conn 0x20002db8
HL [00:08:10.683,288] <wrn> audio_datapath: I2S RX continuing stream
HL [00:08:10.691,284] <wrn> audio_datapath: I2S RX overrun. Single msg
HL [00:08:10.704,315] <inf> audio_datapath: Drft comp state: INIT
HL [00:08:11.243,072] <dbg> bt_audio_stream: bt_audio_stream_iso_accept: acl 0x20002db8
HL [00:08:11.243,072] <dbg> bt_audio_stream: bt_audio_stream_iso_accept: iso_chan 0x2000bb20
HL [00:08:11.440,124] <inf> audio_datapath: Drft comp state: CALIB
HL [00:08:11.441,101] <wrn> audio_datapath: Data received, total underruns: 755
HL [00:08:11.492,218] <wrn> audio_datapath: Data received, total underruns: 756
HL [00:08:11.540,344] <inf> audio_datapath: Drft comp state: OFFSET
HL [00:08:12.021,820] <inf> audio_datapath: Drft comp state: LOCKED
HL [00:08:12.029,510] <inf> audio_datapath: Pres comp state: MEAS
HL [00:08:12.139,495] <inf> audio_datapath: Pres comp state: WAIT
HL [00:08:12.239,501] <inf> audio_datapath: Pres comp state: INIT
HL [00:08:12.249,511] <inf> audio_datapath: Pres comp state: MEAS
HL [00:08:12.359,497] <inf> audio_datapath: Pres comp state: LOCKED
HL [00:08:16.800,872] <inf> cis_headset: Stream stopped
HL [00:08:16.800,903] <dbg> bt_audio_stream: bt_audio_stream_iso_listen: stream 0x2000a728 conn 0x20002db8
HL [00:08:16.801,727] <inf> cis_headset: Disconnected: 0C:C4:13:2F:AD:44 (public) (reason 0x08)
HL [00:08:16.802,673] <inf> cis_headset: Direct advertising to 0C:C4:13:2F:AD:44 (public) started

Parents
  • 0

    Update: Think upgrading the version of the network controller binary has resolved this issue for the demo application. Will see if it resolves timeout in my original use-case. 

  • 0 in reply to kieran.cheung

    Unfortunately upgrading to the most recent version of the SDK has not resolved the timeout when the 5340 is acting as a gateway/client.

    I have tested the Audio Application on versions 2.2.99-dev3 and 2.2.0 and in both instances a timeout occurs when calling bt_audio_stream_enable() while connected to the Earfun headphones. I have no way of knowing whether this is an issue on the headphones or on the client, however the headphones are able to work with Android on the Google Pixel 7.

    The fact that there was also a (now fixed) timeout related issue in the CIS headset mode in a previous version makes me suspect there may be some issue in the gateway mode within the current version? Has the gateway mode been tested with any third party server devices?

    I made only minor adjustments to attempt to use the application with the headphones, setting presentation delay to 25000 instead of 10000 as the headphones require this, and changing the scanning process to look for the name of the headphones. Plus some logs to show when things are happening.

    Here is the log:

    (bt_audio_stream_enable is called just after QOS is set.)

    GW [00:00:00.259,490] <inf> fw_info: ------- DEBUG BUILD -------
    GW [00:00:00.259,490] <inf> fw_info: Compiled for GATEWAY device
    GW [00:00:00.270,111] <inf> board_version: Compatible board/HW version found: 1.0.0
    GW [00:00:02.305,999] <wrn> bt_hci_core: Controller to host flow control not supported
    GW [00:00:02.309,143] <inf> bt_hci_core: No ID address. App must call settings_load()
    GW [00:00:02.309,204] <inf> ble: MAC: 00:00:00:00:00:00 (public)
    GW [00:00:02.309,783] <inf> ble: Controller version: 3310
    GW [00:00:02.403,839] <inf> cis_gateway: Scanning successfully started
    GW [00:00:07.595,367] <inf> cis_gateway: Found Whitelisted Advertiser
    GW [00:00:07.680,114] <inf> cis_gateway: Connected: 70:5A:6F:60:62:71 (public)
    GW [00:00:11.072,418] <inf> cis_gateway: Scanning successfully started
    GW [00:00:11.851,776] <wrn> bt_unicast_client: No space left to parse ASE
    GW [00:00:12.752,319] <inf> cis_gateway: Stream configured 0x2000b5ac
    GW [00:00:12.752,349] <inf> cis_gateway: LEFT sink stream connected
    GW [00:00:12.812,164] <inf> cis_gateway: QOS Set for stream 0x2000b5ac
    GW [00:00:16.834,625] <inf> cis_gateway: Disconnected: 70:5A:6F:60:62:71 (public) (reason 0x08)

  • 0 in reply to Kenneth

    Hi Kenneth,

    If you could check what testing has been done outside the UPF, it would be much appreciated.

    I've seen the thread you posted and seems his initial problem was at the pairing and then location stage, which I haven't had any problems with. I'd specifically be interested if anyone has been able to successfully get a response to the 'enable stream' command with a pair of third party headphones.

  • 0 in reply to kieran.cheung

    I will ask around a bit internally and get back to you. Let me know if you have any findings in the meantime.

    Kenneth

  • 0 in reply to Kenneth

    Following this thread with interest - would be great if there were further updates on the compatibility of the Nordic kit as a gateway device.

  • 0 in reply to ClinicalAudio

    Hello,

    After discussion internally I learned that the gateway at the moment is not very flexible, so you would likely need to match the sample rate, bitrate and presentation delay of the Earfun Air Pro 3. An application log from the nRF5340 gatway may help to see how gateway negotiates with Earfun Air Pro 3.

    The team is currently working on making the gateway more dynamic, so moving forward you can expect that the gateway will automatically apply whatever the headset is supporting (in other words avoid this manual configuration described above).

    Best regards,
    Kenneth

  • 0 in reply to Kenneth

    Hi Kenneth, 

    Thanks for your response. I believe I am currently matching the audio parameters supported by the Earfun Air Pro 3. 

    The only change needed from the default configuration of the gateway demo to match the PACs of these headphones is increasing the presentation delay to 25000 from 10000 us. Everything else can remain the same and matches the Earfun Air Pro 3, although I have also tried with other supported audio parameters.

    My problem isn't an error response with the LE Audio interface, it's a generic BLE timeout when issuing the 'enable' command for a stream, after successfully configuring it.

    So I think the issue has to either be a general Bluetooth connectivity problem, such as the one that caused the timeouts with Android in a previous SDK version (when the device was acting as a headset,) or an assert within these headphones, although as mentioned the Earfuns do work with Android.

    If I knew that the 5340 acting as an audio gateway was able to successfully enable a stream to another off-the-shelf peripheral, that would narrow down the problem to these headphones and I could just purchase that off-the-shelf product if it's out.

    I understand that testing and building compatibility takes time but is there a possibility of receiving info on test results with available off-the-shelf products in the near future? Especially as more become publically available for testing outside UPF.

    Thanks

    Kieran

Reply
  • 0 in reply to Kenneth

    Hi Kenneth, 

    Thanks for your response. I believe I am currently matching the audio parameters supported by the Earfun Air Pro 3. 

    The only change needed from the default configuration of the gateway demo to match the PACs of these headphones is increasing the presentation delay to 25000 from 10000 us. Everything else can remain the same and matches the Earfun Air Pro 3, although I have also tried with other supported audio parameters.

    My problem isn't an error response with the LE Audio interface, it's a generic BLE timeout when issuing the 'enable' command for a stream, after successfully configuring it.

    So I think the issue has to either be a general Bluetooth connectivity problem, such as the one that caused the timeouts with Android in a previous SDK version (when the device was acting as a headset,) or an assert within these headphones, although as mentioned the Earfuns do work with Android.

    If I knew that the 5340 acting as an audio gateway was able to successfully enable a stream to another off-the-shelf peripheral, that would narrow down the problem to these headphones and I could just purchase that off-the-shelf product if it's out.

    I understand that testing and building compatibility takes time but is there a possibility of receiving info on test results with available off-the-shelf products in the near future? Especially as more become publically available for testing outside UPF.

    Thanks

    Kieran

Children
  • 0 in reply to kieran.cheung

    Hello, I received feedback from one in the gruop working with audio, adding it here:

    1. The user tests our headset with Pixel 7 and found the Pixel 7 disconnected after stream start couple seconds later.

    This is a known issue, probably because the Pixel 7 sends a connection parameter request for using 40ms ACL interval, which audio controller is not happy and out of response. From my side I can see that Pixel will try to reconnect the headset again in the latest AOSP Android, and then stream can recover, since Pixel will try to use different connection parameters.

    There might be a quick workaround is that we add connection parameter request callback, return false if interval_min/max is 0x40. But this is something we will check with the audio controller developers.

    It seems during the handshaking, headset will expose the minimal/maximum presentation delay, Pixel chooses the minimal one, but it cannot handle it properly, so glitch happens. We have a PR in the later for telling the Phone uses a higher number.

    2. For the case when nRF5340 gateway connects with Earfun, I would assume Earfun refuse the QoS setting from our gateway. I will check if we can low down the log level to see more details. It is hard to figure out where is the issue (central or peripheral). A sniffer log from Ellisys would provide great help.

    Kenneth

  • 0 in reply to Kenneth

    One question that may help the developers with the debugging: Can you connect to the earbuds with the nRFConnect phone app and see whether there are any LE Audio services there?

    Thanks,
    Kenneth

  • 0 in reply to Kenneth

    Hi Kenneth, 

    Thanks for your response,

    I have noticed the connection interval seems very critical to LE Audio connections with the 5340, but I haven't found any documentation on what exactly is the appropriate value based on the parameters involved. Why does the audio controller not like 40ms for example? 

    I have connected to the headphones via the nRF Connect app and they have Published Audio Capability Service (PACS,) Audio Stream Control Service (ASCS,) Volume Control Service (VCS). I had decoded the PACs on the device (see attached) to check that the parameters I was configuring the stream with were valid.

    Fullscreen Earfun PACs.txt Download 
    06-00-00-00-00 | 13 | 03-01-80-00 | 02-02-13 | 02-03-01 | 05-04-4B-00-64-00 | 02-05-02 | 04 | 03-01-08-00

LC3 Codec
Data (len 0x13):
	-Supported Frequencies: 48000
	-Frame Duration: Supported 7.5 & 10, Preferred 7.5
	-Channel Count: 1
	-Octets per codec frame: Min = 75, Max = 100
	-Max frames per SDU: 2

Meta (len 0x04):
	-Preferred Audio Contexts: Game
-------------------------------------------------------------------------------------------------------------
06-00-00-00-00 | 13 | 03-01-34-00 | 02-02-23 | 02-03-01 | 05-04-28-00-50-00 | 02-05-02 | 04 | 03-01-42-00

LC3 Codec
Data (len 0x13):
	-Supported Frequencies: 16000, 24000, 32000
	-Frame Duration: Supported 7.5 & 10, Preferred 10
	-Channel Count: 1
	-Octets per codec frame: Min = 40, Max = 80
	-Max frames per SDU: 2

Meta (len 0x04):
	-Preferred Audio Contexts: Conversational, Live
-------------------------------------------------------------------------------------------------------------
06-00-00-00-00 | 13 | 03-01-B4-00 | 02-02-23 | 02-03-01 | 05-04-1E-00-9B-00 | 02-05-02 | 04 | 03-01-04-00
LC3 Codec
Data (len 0x13):
	-Supported Frequencies: 16000, 24000, 32000, 48000
	-Frame Duration: Supported 7.5 & 10, Preferred 10
	-Channel Count: 1
	-Octets per codec frame: Min = 30, Max = 155
	-Max frames per SDU: 2

Meta (len 0x04):
	-Preferred Audio Contexts: Media
--------------------------------------------------------------------------------------------------------------

    For QoS the only change I made was to increase the presentation delay to 30000us as the headphones were giving response notifications via the LE Audio service when providing the lower default values. With these changes the configure QoS command appears to give a successful completion callback with no warnings.

    I will look into getting a sniffer log. The way the headphones are behaving during the error looks like it's the headphone that is asserting. It clearly seems to hard-reset before the 5340 detects a timeout. It's just unusual because they work with Android so there must be something different about the connection with the 5340 that it doesn't like.

  • 0 in reply to kieran.cheung

    We are looking into this, can you add the following config in the gateway for getting more information?

    CONFIG_BT_AUDIO_DEBUG_UNICAST_CLIENT=y
    CONFIG_BT_AUDIO_STREAM_LOG_LEVEL_DBG=y
    CONFIG_LOG_BUFFER_SIZE=8192

    Kenneth

  • 0 in reply to Kenneth

    Hi Kenneth,

    Here is the log I get when trying to connect using a build of the 5340 application from version 2.2.99-dev3 with only the following changes in addition to the log flags you mentioned.

    • CONFIG_BT_AUDIO_PRESENTATION_DELAY_US=25000
    • CONFIG_BT_AUDIO_MAX_TRANSPORT_LATENCY_MS=30
    • Connecting to headphones based on their name.

    Fullscreen Connection Attempt Log.txt Download 
    *** Booting Zephyr OS build v3.2.99-ncs1-1547-ge2bec540218d ***
GW [00:00:00.258,728] <inf> fw_info:
         nRF5340 Audio nRF5340 Audio DK cpuapp
         NCS base version: 2.2.99-dev3
         Cmake run : Wed Feb 15 13:52:27 2023
GW [00:00:00.258,728] <inf> fw_info: ------- DEBUG BUILD -------
GW [00:00:00.258,728] <inf> fw_info: Compiled for GATEWAY device
GW [00:00:00.269,348] <inf> board_version: Compatible board/HW version found: 1.0.0
GW [00:00:02.304,779] <wrn> bt_hci_core: Controller to host flow control not supported
GW [00:00:02.307,922] <inf> bt_hci_core: No ID address. App must call settings_load()
GW [00:00:02.307,983] <inf> ble: MAC: 00:00:00:00:00:00 (public)
GW [00:00:02.308,532] <inf> ble: Controller version: 3310
GW [00:00:02.399,932] <dbg> bt_audio_stream: unicast_group_add_stream: group 0x2000ec94 stream 0x2000d1ac dir 1
GW [00:00:02.399,932] <dbg> bt_audio_stream: get_new_iso: Returning new audio_iso for group 0x2000ec94
GW [00:00:02.399,963] <dbg> bt_unicast_client: bt_unicast_client_new_audio_iso: New audio_iso 0x2000e96c
GW [00:00:02.399,963] <dbg> bt_audio_stream: unicast_group_add_stream: Added stream 0x2000d1ac to group 0x2000ec94
GW [00:00:02.399,963] <dbg> bt_audio_stream: unicast_group_add_stream: group 0x2000ec94 stream 0x2000d1d4 dir 1
GW [00:00:02.399,993] <dbg> bt_audio_stream: get_new_iso: Returning new audio_iso for group 0x2000ec94
GW [00:00:02.399,993] <dbg> bt_unicast_client: bt_unicast_client_new_audio_iso: New audio_iso 0x2000e9fc
GW [00:00:02.400,024] <dbg> bt_audio_stream: unicast_group_add_stream: Added stream 0x2000d1d4 to group 0x2000ec94
GW [00:00:02.400,024] <dbg> bt_audio_stream: bt_audio_cig_create: group 0x2000ec94 qos 0x20000420
GW [00:00:02.400,878] <dbg> cis_gateway: le_audio_play_pause_cb: Play/pause cb, state: 1
GW [00:00:02.400,939] <dbg> cis_gateway: bond_check: Stored bonding found: 70:5A:6F:60:62:71 (public)
GW [00:00:02.403,137] <inf> cis_gateway: Scanning successfully started
GW [00:00:08.131,042] <inf> cis_gateway: Found Whitelisted Advertiser
GW [00:00:08.229,888] <inf> cis_gateway: Connected: 70:5A:6F:60:62:71 (public)
GW [00:00:08.730,285] <dbg> cis_gateway: security_changed_cb: Security changed: level 2
GW [00:00:09.031,494] <dbg> bt_unicast_client: unicast_client_read_func: conn 0x20005470 err 0x00 len 61
GW [00:00:09.031,494] <dbg> bt_unicast_client: unicast_client_read_func: handle 0x004b
GW [00:00:09.031,494] <dbg> bt_unicast_client: unicast_client_read_func: pac #0
GW [00:00:09.031,524] <dbg> bt_unicast_client: unicast_client_ep_set_codec: ep (nil) codec id 0x06 cid 0x0000 vid 0x0000 len 19
GW [00:00:09.031,524] <dbg> bt_unicast_client: unicast_client_codec_config_store: #0 type 0x01 len 2
GW [00:00:09.031,555] <dbg> bt_unicast_client: unicast_client_codec_config_store: data
                                               80 00                                            |..
GW [00:00:09.031,555] <dbg> bt_unicast_client: unicast_client_codec_config_store: #1 type 0x02 len 1
GW [00:00:09.031,555] <dbg> bt_unicast_client: unicast_client_codec_config_store: data
                                               13                                               |.
GW [00:00:09.031,585] <dbg> bt_unicast_client: unicast_client_codec_config_store: #2 type 0x03 len 1
GW [00:00:09.031,585] <dbg> bt_unicast_client: unicast_client_codec_config_store: data
                                               01                                               |.
GW [00:00:09.031,616] <dbg> bt_unicast_client: unicast_client_codec_config_store: #3 type 0x04 len 4
GW [00:00:09.031,616] <dbg> bt_unicast_client: unicast_client_codec_config_store: data
                                               4b 00 64 00                                      |K.d.
GW [00:00:09.031,616] <dbg> bt_unicast_client: unicast_client_codec_config_store: #4 type 0x05 len 1
GW [00:00:09.031,646] <dbg> bt_unicast_client: unicast_client_codec_config_store: data
                                               02                                               |.
GW [00:00:09.031,646] <dbg> bt_unicast_client: unicast_client_ep_set_metadata: ep (nil) len 4 codec 0x2000f218
GW [00:00:09.031,677] <dbg> bt_unicast_client: unicast_client_codec_metadata_store: #0 type 0x01 len 2
GW [00:00:09.031,677] <dbg> bt_unicast_client: unicast_client_codec_metadata_store: data
                                               08 00                                            |..
GW [00:00:09.031,677] <dbg> bt_unicast_client: unicast_client_read_func: pac 0x2000f214 codec 0x06 config count 5 meta count 1
GW [00:00:09.031,707] <dbg> bt_unicast_client: unicast_client_read_func: pac #1
GW [00:00:09.031,707] <dbg> bt_unicast_client: unicast_client_ep_set_codec: ep (nil) codec id 0x06 cid 0x0000 vid 0x0000 len 19
GW [00:00:09.031,707] <dbg> bt_unicast_client: unicast_client_codec_config_store: #0 type 0x01 len 2
GW [00:00:09.031,738] <dbg> bt_unicast_client: unicast_client_codec_config_store: data
                                               34 00                                            |4.
GW [00:00:09.031,738] <dbg> bt_unicast_client: unicast_client_codec_config_store: #1 type 0x02 len 1
GW [00:00:09.031,768] <dbg> bt_unicast_client: unicast_client_codec_config_store: data
                                               23                                               |#
GW [00:00:09.031,768] <dbg> bt_unicast_client: unicast_client_codec_config_store: #2 type 0x03 len 1
GW [00:00:09.031,768] <dbg> bt_unicast_client: unicast_client_codec_config_store: data
                                               01                                               |.
GW [00:00:09.031,799] <dbg> bt_unicast_client: unicast_client_codec_config_store: #3 type 0x04 len 4
GW [00:00:09.031,799] <dbg> bt_unicast_client: unicast_client_codec_config_store: data
                                               28 00 50 00                                      |(.P.
GW [00:00:09.031,799] <dbg> bt_unicast_client: unicast_client_codec_config_store: #4 type 0x05 len 1
GW [00:00:09.031,829] <dbg> bt_unicast_client: unicast_client_codec_config_store: data
                                               02                                               |.
GW [00:00:09.031,829] <dbg> bt_unicast_client: unicast_client_ep_set_metadata: ep (nil) len 4 codec 0x2000f280
GW [00:00:09.031,829] <dbg> bt_unicast_client: unicast_client_codec_metadata_store: #0 type 0x01 len 2
GW [00:00:09.031,860] <dbg> bt_unicast_client: unicast_client_codec_metadata_store: data
                                               42 00                                            |B.
GW [00:00:09.031,860] <dbg> bt_unicast_client: unicast_client_read_func: pac 0x2000f27c codec 0x06 config count 5 meta count 1
GW [00:00:09.031,890] <dbg> bt_unicast_client: unicast_client_pacs_context_discover: conn 0x20005470 params 0x2000d130
GW [00:00:09.230,285] <dbg> bt_unicast_client: unicast_client_pacs_context_read_func: conn 0x20005470 err 0x00 len 4
GW [00:00:09.230,285] <dbg> bt_unicast_client: unicast_client_pacs_context_read_func: pac 0x2000f214 context 0x0fff
GW [00:00:09.230,316] <dbg> bt_unicast_client: unicast_client_pacs_context_read_func: pac 0x2000f27c context 0x0fff
GW [00:00:09.230,316] <dbg> bt_unicast_client: unicast_client_pacs_location_discover: conn 0x20005470 params 0x2000d130
GW [00:00:09.970,977] <dbg> bt_unicast_client: unicast_client_pacs_location_discover_cb: conn 0x20005470 attr 0x20015a54 handle 0x0057
GW [00:00:09.971,038] <dbg> bt_unicast_client: unicast_client_pacs_location_read: conn 0x20005470 params 0x2000d130
GW [00:00:10.090,576] <dbg> bt_unicast_client: unicast_client_pacs_location_read_func: conn 0x20005470 err 0x00 len 4
GW [00:00:10.090,606] <dbg> bt_unicast_client: unicast_client_pacs_location_read_func: dir 1 loc 3
GW [00:00:10.090,667] <dbg> cis_gateway: bond_check: Stored bonding found: 70:5A:6F:60:62:71 (public)
GW [00:00:10.091,400] <inf> cis_gateway: Scanning successfully started
GW [00:00:10.091,400] <dbg> bt_unicast_client: unicast_client_pacs_avail_ctx_discover: conn 0x20005470 params 0x2000d130
GW [00:00:10.661,041] <dbg> bt_unicast_client: unicast_client_pacs_avail_ctx_discover_cb: conn 0x20005470 attr 0x20015a54 handle 0x0069
GW [00:00:10.661,041] <dbg> bt_unicast_client: unicast_client_pacs_avail_ctx_discover_cb: Subscribing to handle 105
GW [00:00:10.661,102] <dbg> bt_unicast_client: unicast_client_pacs_avail_ctx_read: conn 0x20005470 params 0x2000d130
GW [00:00:10.780,364] <dbg> bt_unicast_client: unicast_client_pacs_avail_ctx_read_func: conn 0x20005470 err 0x00 len 4
GW [00:00:10.780,395] <dbg> bt_unicast_client: unicast_client_pacs_avail_ctx_read_func: sink context 15, source context 75
GW [00:00:10.780,487] <dbg> cis_gateway: available_contexts_cb: conn: 70:5A:6F:60:62:71 (public), snk ctx 15 src ctx 75

GW [00:00:10.780,487] <dbg> bt_unicast_client: unicast_client_ase_discover: conn 0x20005470 params 0x2000d130
GW [00:00:10.900,482] <dbg> bt_unicast_client: unicast_client_ase_read_func: conn 0x20005470 err 0x00 len 2
GW [00:00:10.900,482] <dbg> bt_unicast_client: unicast_client_ase_read_func: handle 0x0086
GW [00:00:10.900,482] <dbg> bt_unicast_client: unicast_client_ep_init: ep 0x2000eea4 dir 0x01 handle 0x0086
GW [00:00:10.900,543] <dbg> bt_unicast_client: unicast_client_ep_set_status: ep 0x2000eea4 handle 0x0086 id 0x01 dir 1 state idle -> idle
GW [00:00:10.900,543] <dbg> bt_unicast_client: unicast_client_ep_subscribe: ep 0x2000eea4 handle 0x86
GW [00:00:10.900,573] <dbg> bt_unicast_client: unicast_client_ase_read_func: conn 0x20005470 err 0x00 len 2
GW [00:00:10.900,604] <dbg> bt_unicast_client: unicast_client_ase_read_func: handle 0x0089
GW [00:00:10.900,604] <dbg> bt_unicast_client: unicast_client_ep_init: ep 0x2000ef90 dir 0x01 handle 0x0089
GW [00:00:10.900,634] <dbg> bt_unicast_client: unicast_client_ep_set_status: ep 0x2000ef90 handle 0x0089 id 0x02 dir 1 state idle -> idle
GW [00:00:10.900,665] <dbg> bt_unicast_client: unicast_client_ep_subscribe: ep 0x2000ef90 handle 0x89
GW [00:00:10.900,695] <dbg> bt_unicast_client: unicast_client_ase_read_func: conn 0x20005470 err 0x00 len 2
GW [00:00:10.900,695] <dbg> bt_unicast_client: unicast_client_ase_read_func: handle 0x008c
GW [00:00:10.900,695] <wrn> bt_unicast_client: No space left to parse ASE
GW [00:00:10.900,726] <dbg> bt_unicast_client: unicast_client_ase_cp_discover: conn 0x20005470 params 0x2000d130
GW [00:00:11.770,996] <dbg> bt_unicast_client: unicast_client_cp_discover_func: conn 0x20005470 attr 0x20015a54 handle 0x0098
GW [00:00:11.770,996] <dbg> bt_unicast_client: unicast_client_ep_set_cp: conn 0x20005470 0x0098
GW [00:00:11.771,057] <dbg> cis_gateway: discover_sink_cb: Sink discover complete: err 0
GW [00:00:11.771,087] <dbg> bt_audio_stream: bt_audio_stream_config: conn 0x20005470 stream 0x2000d1ac, ep 0x2000ef90 codec 0x200003bc codec id 0x06 codec cid 0x0000 codec vid 0x0000
GW [00:00:11.771,087] <dbg> bt_audio_stream: bt_audio_stream_attach: conn 0x20005470 stream 0x2000d1ac ep 0x2000ef90 codec 0x200003bc
GW [00:00:11.771,087] <dbg> bt_unicast_client: unicast_client_ep_config: ep 0x2000ef90 buf 0x20001314 codec 0x200003bc
GW [00:00:11.771,087] <dbg> bt_unicast_client: unicast_client_ep_config: id 0x02 dir 0x01 codec 0x06
GW [00:00:11.771,118] <dbg> bt_unicast_client: unicast_client_codec_data_add: #0: data type 0x01 len 1
GW [00:00:11.771,118] <dbg> bt_unicast_client: unicast_client_codec_data_add: data
                                               08                                               |.
GW [00:00:11.771,179] <dbg> bt_unicast_client: unicast_client_codec_data_add: #1: data type 0x02 len 1
GW [00:00:11.771,179] <dbg> bt_unicast_client: unicast_client_codec_data_add: data
                                               01                                               |.
GW [00:00:11.771,209] <dbg> bt_unicast_client: unicast_client_codec_data_add: #2: data type 0x03 len 4
GW [00:00:11.771,209] <dbg> bt_unicast_client: unicast_client_codec_data_add: data
                                               01 00 00 00                                      |....
GW [00:00:11.771,240] <dbg> bt_unicast_client: unicast_client_codec_data_add: #3: data type 0x04 len 2
GW [00:00:11.771,240] <dbg> bt_unicast_client: unicast_client_codec_data_add: data
                                               78 00                                            |x.
GW [00:00:11.771,270] <dbg> bt_unicast_client: bt_unicast_client_ep_send: conn 0x20005470 ep 0x2000ef90 buf 0x20001314 len 27
GW [00:00:11.890,960] <dbg> bt_unicast_client: unicast_client_ep_notify: conn 0x20005470 ep 0x2000ef90 len 41
GW [00:00:11.890,991] <dbg> bt_unicast_client: unicast_client_ep_set_status: ep 0x2000ef90 handle 0x0089 id 0x02 dir 1 state idle -> codec-configured
GW [00:00:11.890,991] <dbg> bt_unicast_client: unicast_client_ep_config_state: dir 0x01 unframed_supported 0x01 phy 0x02 rtn 15 latency 4000 pd_min 25000 pd_max 40000 codec 0x06
GW [00:00:11.890,991] <dbg> bt_unicast_client: unicast_client_ep_set_codec: ep 0x2000ef90 codec id 0x06 cid 0x0000 vid 0x0000 len 16
GW [00:00:11.891,021] <dbg> bt_unicast_client: unicast_client_codec_config_store: #0 type 0x01 len 1
GW [00:00:11.891,021] <dbg> bt_unicast_client: unicast_client_codec_config_store: data
                                               08                                               |.
GW [00:00:11.891,052] <dbg> bt_unicast_client: unicast_client_codec_config_store: #1 type 0x02 len 1
GW [00:00:11.891,052] <dbg> bt_unicast_client: unicast_client_codec_config_store: data
                                               01                                               |.
GW [00:00:11.891,052] <dbg> bt_unicast_client: unicast_client_codec_config_store: #2 type 0x03 len 4
GW [00:00:11.891,082] <dbg> bt_unicast_client: unicast_client_codec_config_store: data
                                               01 00 00 00                                      |....
GW [00:00:11.891,082] <dbg> bt_unicast_client: unicast_client_codec_config_store: #3 type 0x04 len 2
GW [00:00:11.891,113] <dbg> bt_unicast_client: unicast_client_codec_config_store: data
                                               78 00                                            |x.
GW [00:00:11.891,113] <inf> cis_gateway: LEFT sink stream connected
GW [00:00:11.891,113] <dbg> bt_audio_stream: bt_audio_stream_qos: conn 0x20005470 group 0x2000ec94
GW [00:00:11.891,143] <dbg> bt_unicast_client: bt_unicast_client_ep_qos: ep 0x2000ef90 buf 0x20001314 qos 0x20000420
GW [00:00:11.891,174] <dbg> bt_unicast_client: bt_unicast_client_ep_qos: id 0x02 cig 0x00 cis 0x00 interval 10000 framing 0x00 phy 0x02 sdu 120 rtn 2 latency 30 pd 25000
GW [00:00:11.891,174] <dbg> bt_unicast_client: bt_unicast_client_ep_send: conn 0x20005470 ep 0x2000ef90 buf 0x20001314 len 18
GW [00:00:11.950,744] <dbg> bt_unicast_client: unicast_client_ep_notify: conn 0x20005470 ep 0x2000ef90 len 17
GW [00:00:11.950,775] <dbg> bt_unicast_client: unicast_client_ep_set_status: ep 0x2000ef90 handle 0x0089 id 0x02 dir 1 state codec-configured -> qos-configured
GW [00:00:11.950,775] <dbg> bt_unicast_client: unicast_client_ep_qos_update: ep 0x2000ef90 dir 1 audio_iso 0x2000e96c
GW [00:00:11.950,775] <dbg> bt_unicast_client: unicast_client_ep_qos_state: dir 0x01 cig 0x00 cis 0x00 codec 0x06 interval 10000 framing 0x00 phy 0x02 rtn 2 latency 30 pd 25000
GW [00:00:11.950,805] <dbg> bt_audio_stream: bt_audio_stream_enable: stream 0x2000d1ac
GW [00:00:11.950,805] <dbg> bt_unicast_client: bt_unicast_client_enable: stream 0x2000d1ac
GW [00:00:11.950,805] <dbg> bt_unicast_client: unicast_client_ep_enable: ep 0x2000ef90 buf 0x20001314 metadata count 1
GW [00:00:11.950,836] <dbg> bt_unicast_client: unicast_client_ep_enable: id 0x02
GW [00:00:11.950,836] <dbg> bt_unicast_client: unicast_client_codec_data_add: #0: meta type 0x02 len 2
GW [00:00:11.950,866] <dbg> bt_unicast_client: unicast_client_codec_data_add: meta
                                               04 00                                            |..
GW [00:00:11.950,866] <dbg> bt_unicast_client: bt_unicast_client_ep_send: conn 0x20005470 ep 0x2000ef90 buf 0x20001314 len 8
GW [00:00:15.981,170] <dbg> bt_unicast_client: unicast_client_cp_notify: conn 0x20005470 len 0
GW [00:00:15.981,170] <dbg> bt_unicast_client: unicast_client_cp_notify: Unsubscribed
GW [00:00:15.981,170] <dbg> bt_unicast_client: unicast_client_ep_notify: conn 0x20005470 ep 0x2000ef90 len 0
GW [00:00:15.981,201] <dbg> bt_unicast_client: unicast_client_ep_notify: Unsubscribed
GW [00:00:15.981,201] <dbg> bt_unicast_client: unicast_client_ep_notify: conn 0x20005470 ep 0x2000eea4 len 0
GW [00:00:15.981,201] <dbg> bt_unicast_client: unicast_client_ep_notify: Unsubscribed
GW [00:00:15.981,231] <dbg> bt_unicast_client: unicast_client_disconnected: conn 0x20005470 reason 0x08
GW [00:00:15.981,231] <dbg> bt_unicast_client: unicast_client_ep_reset: conn 0x20005470
GW [00:00:15.981,231] <dbg> bt_unicast_client: unicast_client_reset: ep 0x2000eea4
GW [00:00:15.981,262] <dbg> bt_audio_stream: bt_audio_stream_reset: stream (nil)
GW [00:00:15.981,262] <dbg> bt_unicast_client: unicast_client_reset: ep 0x2000ef90
GW [00:00:15.981,292] <dbg> bt_audio_stream: bt_audio_stream_reset: stream 0x2000d1ac
GW [00:00:15.981,292] <dbg> bt_audio_stream: bt_audio_stream_detach: stream 0x2000d1ac
GW [00:00:15.981,292] <dbg> bt_audio_stream: bt_audio_stream_disconnect: stream 0x2000d1ac iso (nil)
GW [00:00:15.981,414] <inf> cis_gateway: Disconnected: 70:5A:6F:60:62:71 (public) (reason 0x08)
GW [00:00:15.981,506] <dbg> cis_gateway: bond_check: Stored bonding found: 70:5A:6F:60:62:71 (public)
GW [00:00:15.981,506] <inf> cis_gateway: Scanning successfully started
GW [00:00:17.684,173] <inf> cis_gateway: Found Whitelisted Advertiser
GW [00:00:17.714,141] <inf> cis_gateway: Connected: 70:5A:6F:60:62:71 (public)
GW [00:00:17.914,428] <err> cis_gateway: Security failed: level 1 err 2
GW [00:00:18.015,075] <wrn> bt_att: Not connected
GW [00:00:18.015,106] <err> bt_conn: not connected!
GW [00:00:18.016,296] <dbg> bt_unicast_client: unicast_client_pacs_avail_ctx_notify_cb: conn 0x20005470 len 0
GW [00:00:18.016,296] <dbg> bt_unicast_client: unicast_client_pacs_avail_ctx_notify_cb: Unsubscribed
GW [00:00:18.016,326] <wrn> bt_gatt: conn 0x20005470 err 0x0e
GW [00:00:18.016,845] <dbg> bt_unicast_client: unicast_client_disconnected: conn 0x20005470 reason 0x16
GW [00:00:18.016,876] <dbg> bt_unicast_client: unicast_client_ep_reset: conn 0x20005470
GW [00:00:18.016,876] <dbg> bt_unicast_client: unicast_client_reset: ep 0x2000eea4
GW [00:00:18.016,906] <dbg> bt_audio_stream: bt_audio_stream_reset: stream (nil)
GW [00:00:18.016,906] <dbg> bt_unicast_client: unicast_client_reset: ep 0x2000ef90
GW [00:00:18.016,906] <dbg> bt_audio_stream: bt_audio_stream_reset: stream (nil)
GW [00:00:18.016,998] <inf> cis_gateway: Disconnected: 70:5A:6F:60:62:71 (public) (reason 0x16)
GW [00:00:18.016,998] <wrn> cis_gateway: Connection not found
GW [00:00:18.017,028] <wrn> cis_gateway: Unknown connection
GW [00:00:18.017,089] <dbg> cis_gateway: bond_check: Stored bonding found: 70:5A:6F:60:62:71 (public)
GW [00:00:18.017,639] <inf> cis_gateway: Scanning successfully started
GW [00:00:19.174,102] <inf> cis_gateway: Found Whitelisted Advertiser
GW [00:00:19.311,676] <inf> cis_gateway: Connected: 70:5A:6F:60:62:71 (public)
GW [00:00:19.511,932] <err> cis_gateway: Security failed: level 1 err 2
GW [00:00:19.612,640] <wrn> bt_att: Not connected
GW [00:00:19.612,670] <err> bt_conn: not connected!

    After the timeout, at ~15.9s the device then continuously finds and fails to pair to the headphones until I cycle both. I believe this is because the initial headphone that the gateway tries to enable the stream to asserts (it visibly seems to blink red and turn off while the other continues blinking for advertising) and the other one keeps advertising, but security fails because of (I'm guessing) some spec behaviour around pairing to the same address.

    I have also reported this to the headphone manufacturer, but as I noted they work with Android which makes it harder to dismiss the problem as only relevant to the headphone and not the 5340.

    Thanks

Related
Terms of service