nRF5340 LE Audio Samsung Galaxy Buds2 Pro - Multiple Problems

[ksmith197]

Hello,

I using the Samsung Galaxy Buds2 Pro headphones to connect to the latest v2.4.0 nRF SDK. I am using the LE Audio demo code as gateway. The demo connects successfully out of the box to the headphones, with some modifications to the prj.conf file, using the nRF5340 Audio DK. For my project needs, I have both source and sink enabled via CONFIG_STREAM_BIDIRECTIONAL.

CONFIG_AUDIO_DEV=2

CONFIG_BT_DEVICE_NAME="Galaxy Buds2 Pro"
#QOS will fail without this
CONFIG_BT_AUDIO_PRESENTATION_DELAY_US=40000
#Seem to get failed to discover without this
CONFIG_BLE_ACL_CONN_INTERVAL=72
CONFIG_BT_AUDIO_MAX_TRANSPORT_LATENCY_MS=100
CONFIG_LOG_BUFFER_SIZE=8192
CONFIG_BT_AUDIO_RETRANSMITS=2
CONFIG_BT_BAP_UNICAST_CLIENT_ASE_SRC_COUNT=2

CONFIG_STREAM_BIDIRECTIONAL=y
CONFIG_WALKIE_TALKIE_DEMO=y

CONFIG_AUDIO_SOURCE_I2S=y
CONFIG_BT_BONDABLE=n

CONFIG_BT_VCP_VOL_CTLR=n

Problem #1 - Controller Crashes

If you connect to the right headset first, then connect to the left headset, the"ble5-ctr-rpmsg_3349" controller crashes. I believe this also happened on the 3330 controller as well.

The crash happens after calling bt_bap_stream_start on the Left SINK. This only happens if you connect to the right headset first, followed by the left.

Once the controller crashes, the next call to bt_hci_cmd_send_sync will fail on semaphore take "timeout with err -11". This usually happens either on the next le_audio_send stream send OR on the ble_core.c watchdog call to net_core_ctrl_version_get.

Log:

         nRF5340 Audio nRF5340 Audio DK cpuapp
         NCS base version: 2.4.0
         Cmake run : Tue Jun 13 05:32:12 2023
GW [00:00:00.258,209] <inf> fw_info: ------- DEBUG BUILD -------
GW [00:00:00.258,239] <inf> fw_info: Compiled for GATEWAY device
GW [00:00:00.268,859] <inf> board_version: Compatible board/HW version found: 1.0.0
GW [00:00:00.305,755] <wrn> bt_hci_core: Controller to host flow control not supported
GW [00:00:00.308,898] <inf> bt_hci_core: No ID address. App must call settings_load()
GW [00:00:00.308,959] <inf> ble: MAC: 00:00:00:00:00:00 (public)
GW [00:00:00.309,509] <inf> ble: Controller version: 3349
GW [00:00:00.312,500] <err> settings: set-value failure. key: bt/name error(-2)
GW [00:00:00.312,591] <inf> bt_hci_core: Identity: FD:60:E5:B4:2A:20 (random)
GW [00:00:00.312,622] <inf> bt_hci_core: HCI: version 5.2 (0x0b) revision 0x0d15, manufacturer 0x07e8
GW [00:00:00.312,622] <inf> bt_hci_core: LMP: version 5.2 (0x0b) subver 0x0d15
GW [00:00:00.430,725] <inf> cis_gateway: Scanning successfully started
GW [00:00:05.272,583] <inf> cis_gateway: Connected: 7F:3B:83:F5:3B:A8 (random)
GW [00:00:07.189,117] <err> cis_gateway: <<<<< security_changed_cb >>>>>
GW [00:00:07.189,117] <err> cis_gateway: <<<<< discover_sink >>>>>
GW [00:00:07.457,885] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:08.467,346] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:08.467,346] <wrn> cis_gateway: BT_AUDIO_LOCATION_FRONT_RIGHT 0x20005698
GW [00:00:08.468,078] <inf> cis_gateway: Scanning successfully started
GW [00:00:08.857,391] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:08.917,388] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:08.917,419] <wrn> cis_gateway: More than one sink endpoints found, ep idx 0 is used by default
GW [00:00:09.217,315] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:09.217,437] <err> cis_gateway: <<<<< discover_source >>>>>
GW [00:00:09.257,995] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:09.258,026] <inf> cis_gateway: RIGHT sink stream configured
GW [00:00:09.258,544] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:09.577,362] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:09.857,421] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:10.107,452] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:10.147,583] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:10.147,583] <inf> cis_gateway: RIGHT source stream configured
GW [00:00:10.207,916] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:10.207,946] <inf> cis_gateway: Enable stream 0x200023cc
GW [00:00:10.208,404] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:10.208,465] <inf> cis_gateway: Enable stream 0x200021ac
GW [00:00:10.257,415] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:10.258,331] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:10.427,459] <err> cis_gateway: <<<<< stream_started_cb >>>>>
GW [00:00:10.427,459] <inf> cis_gateway: Stream 0x200021ac started
GW [00:00:10.453,308] <wrn> bt_hci_core: opcode 0x2061 status 0x0c
GW [00:00:10.921,203] <err> cis_gateway: <<<<< stream_started_cb >>>>>
GW [00:00:10.921,234] <inf> cis_gateway: Stream 0x200023cc started
GW [00:00:12.058,898] <inf> cis_gateway: Connected: 71:09:B2:4D:BC:12 (random)
GW [00:00:14.863,433] <err> cis_gateway: <<<<< security_changed_cb >>>>>
GW [00:00:14.863,464] <err> cis_gateway: <<<<< discover_sink >>>>>
GW [00:00:15.131,622] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:15.439,147] <wrn> audio_datapath: In I2S TX underrun condition, total: 5000
GW [00:00:16.901,458] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:16.901,458] <wrn> cis_gateway: BT_AUDIO_LOCATION_FRONT_LEFT 0x20005760
GW [00:00:16.901,458] <inf> cis_gateway: All headsets connected
GW [00:00:17.471,496] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:17.531,494] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:17.531,524] <wrn> cis_gateway: More than one sink endpoints found, ep idx 0 is used by default
GW [00:00:18.071,441] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:18.071,563] <err> cis_gateway: <<<<< discover_source >>>>>
GW [00:00:18.141,662] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:18.141,693] <inf> cis_gateway: LEFT sink stream configured
GW [00:00:18.151,611] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:18.651,519] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:19.131,591] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:19.551,605] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:19.641,693] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:19.641,723] <inf> cis_gateway: LEFT source stream configured
GW [00:00:19.751,586] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:19.751,617] <inf> cis_gateway: Enable stream 0x20001f0c
GW [00:00:19.761,718] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:19.761,779] <inf> cis_gateway: Enable stream 0x20001cec
GW [00:00:19.821,533] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:19.851,562] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:19.857,177] <wrn> audio_datapath: I2S RX overrun. Single msg
GW [00:00:19.942,169] <wrn> audio_datapath: I2S RX continuing stream
GW [00:00:19.962,158] <wrn> audio_datapath: I2S RX overrun. Single msg
GW [00:00:20.439,147] <wrn> audio_datapath: In I2S TX underrun condition, total: 10000
GW [00:00:25.439,147] <wrn> audio_datapath: In I2S TX underrun condition, total: 15000
ASSERTION FAIL [err == 0] @ WEST_TOPDIR/zephyr/subsys/bluetooth/host/hci_core.c:330
        command opcode 0x2061 timeout with err -11
GW [00:00:29.958,007] <err> os: r0/a1:  0x00000003  r1/a2:  0x00000002  r2/a3:  0x00000001
GW [00:00:29.958,038] <err> os: r3/a4:  0x0000014a r12/ip:  0x00407fd0 r14/lr:  0x00020c95
GW [00:00:29.958,038] <err> os:  xpsr:  0x41100000
GW [00:00:29.958,038] <err> os: s[ 0]:  0x00000000  s[ 1]:  0x0000001c  s[ 2]:  0x00000000  s[ 3]:  0x000000a2
GW [00:00:29.958,038] <err> os: s[ 4]:  0x00000010  s[ 5]:  0x0000001a  s[ 6]:  0x00000000  s[ 7]:  0x000000a2
GW [00:00:29.958,068] <err> os: s[ 8]:  0x00000000  s[ 9]:  0x000000a2  s[10]:  0x00000003  s[11]:  0x00000002
GW [00:00:29.958,068] <err> os: s[12]:  0x00000000  s[13]:  0x00000000  s[14]:  0x00000031  s[15]:  0x00000000
GW [00:00:29.958,068] <err> os: fpscr:  0x20000010
GW [00:00:29.958,099] <err> os: Faulting instruction address (r15/pc): 0x00020ca0
GW [00:00:29.958,099] <err> os: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0
GW [00:00:29.958,129] <err> os: Current thread: 0x200018c0 (ENCODER)
GW [00:00:29.958,129] <err> error_handler: Caught system error -- reason 3. Entering infinite loop

Problem #2 - Connection constantly disconnects

There seems to be a possible timing issue when connecting a headset stream, then starting the scan / connection to the other headset.

After starting the left headset stream, when you start scanning / connecting to the right headset, the left headset drops connection. It happens as soon as the right headset starts scan / connection. I have noticed that if you start searching for the right headset later in time / further in the code connection sequence, this happens much less frequently. The ACL scan is originally in unicast_client_location_cb. If I move the ACL scan to discover_source_cb or stream_enabled_cb, the issue happens much less frequently. If this is time dependent, then this is also likely a problem because as we add code to the rest of the system, time could change again and cause the issue to come back.

         nRF5340 Audio nRF5340 Audio DK cpuapp
         NCS base version: 2.4.0
         Cmake run : Tue Jun 13 05:32:12 2023
GW [00:00:00.259,490] <inf> fw_info: ------- DEBUG BUILD -------
GW [00:00:00.259,521] <inf> fw_info: Compiled for GATEWAY device
GW [00:00:00.270,141] <inf> board_version: Compatible board/HW version found: 1.0.0
GW [00:00:00.307,037] <wrn> bt_hci_core: Controller to host flow control not supported
GW [00:00:00.310,150] <inf> bt_hci_core: No ID address. App must call settings_load()
GW [00:00:00.310,241] <inf> ble: MAC: 00:00:00:00:00:00 (public)
GW [00:00:00.310,791] <inf> ble: Controller version: 3349
GW [00:00:00.313,781] <err> settings: set-value failure. key: bt/name error(-2)
GW [00:00:00.313,873] <inf> bt_hci_core: Identity: FD:60:E5:B4:2A:20 (random)
GW [00:00:00.313,903] <inf> bt_hci_core: HCI: version 5.2 (0x0b) revision 0x0d15, manufacturer 0x07e8
GW [00:00:00.313,903] <inf> bt_hci_core: LMP: version 5.2 (0x0b) subver 0x0d15
GW [00:00:00.432,067] <inf> cis_gateway: Scanning successfully started
GW [00:00:00.517,395] <inf> cis_gateway: Connected: 60:20:E9:4A:5E:67 (random)
GW [00:00:02.330,261] <err> cis_gateway: <<<<< security_changed_cb >>>>>
GW [00:00:02.330,291] <err> cis_gateway: <<<<< discover_sink >>>>>
GW [00:00:02.599,548] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:03.478,485] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:03.478,485] <wrn> cis_gateway: BT_AUDIO_LOCATION_FRONT_LEFT 0x20005698
GW [00:00:03.479,217] <inf> cis_gateway: Scanning successfully started
GW [00:00:03.625,518] <inf> cis_gateway: Connected: 4B:D7:D6:29:40:2F (random)
GW [00:00:03.878,540] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:03.918,548] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:03.918,579] <wrn> cis_gateway: More than one sink endpoints found, ep idx 0 is used by default
GW [00:00:04.308,471] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:04.308,593] <err> cis_gateway: <<<<< discover_source >>>>>
GW [00:00:04.368,713] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:04.368,713] <inf> cis_gateway: LEFT sink stream configured
GW [00:00:04.369,262] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:04.718,963] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:05.078,552] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:05.378,601] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:05.419,189] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:05.419,189] <inf> cis_gateway: LEFT source stream configured
GW [00:00:05.489,044] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:05.489,105] <inf> cis_gateway: Enable stream 0x20001f0c
GW [00:00:05.489,593] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:05.489,654] <inf> cis_gateway: Enable stream 0x20001cec
GW [00:00:05.521,972] <err> cis_gateway: <<<<< security_changed_cb >>>>>
GW [00:00:05.522,003] <err> cis_gateway: <<<<< discover_sink >>>>>
GW [00:00:05.528,533] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:05.539,001] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:05.539,855] <wrn> bt_hci_core: opcode 0x206f status 0x0c
GW [00:00:05.540,100] <wrn> bt_hci_core: opcode 0x206f status 0x12
GW [00:00:05.540,130] <inf> cis_gateway: Stream 0x20001f0c stopped. Reason 13
GW [00:00:05.540,130] <wrn> cis_gateway: Unknown stream
GW [00:00:05.540,130] <inf> cis_gateway: Stream 0x20001cec stopped. Reason 13
GW [00:00:05.790,588] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:06.039,703] <wrn> bt_conn: no transition connecting
GW [00:00:06.040,222] <wrn> bt_hci_core: opcode 0x206f status 0x0c
GW [00:00:06.040,496] <wrn> bt_hci_core: opcode 0x206f status 0x12
GW [00:00:06.040,496] <inf> cis_gateway: Stream 0x20001f0c stopped. Reason 13
GW [00:00:06.040,496] <wrn> cis_gateway: Unknown stream
GW [00:00:06.040,527] <inf> cis_gateway: Stream 0x20001cec stopped. Reason 13
GW [00:00:06.502,532] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:06.502,532] <wrn> cis_gateway: BT_AUDIO_LOCATION_FRONT_RIGHT 0x20005760
GW [00:00:06.502,532] <inf> cis_gateway: All headsets connected
GW [00:00:06.872,558] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:06.912,567] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:06.912,597] <wrn> cis_gateway: More than one sink endpoints found, ep idx 0 is used by default
GW [00:00:07.292,510] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:07.292,633] <err> cis_gateway: <<<<< discover_source >>>>>
GW [00:00:07.313,171] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:07.313,201] <inf> cis_gateway: RIGHT sink stream configured
GW [00:00:07.313,751] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:07.662,567] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:08.012,603] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:08.272,644] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:08.313,201] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:08.313,232] <inf> cis_gateway: RIGHT source stream configured
GW [00:00:08.372,619] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:08.372,680] <inf> cis_gateway: Enable stream 0x200023cc
GW [00:00:08.373,138] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:08.373,199] <inf> cis_gateway: Enable stream 0x200021ac
GW [00:00:08.442,596] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:08.443,511] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:10.444,152] <err> cis_gateway: Failed to establish CIS, ret = -16
GW [00:00:10.463,104] <wrn> bt_hci_core: opcode 0x206f status 0x0c
GW [00:00:10.463,531] <wrn> bt_hci_core: opcode 0x206f status 0x12
GW [00:00:10.463,562] <inf> cis_gateway: Stream 0x200023cc stopped. Reason 13
GW [00:00:10.463,562] <wrn> cis_gateway: Unknown stream
GW [00:00:10.463,562] <inf> cis_gateway: Stream 0x200021ac stopped. Reason 13
GW [00:00:10.464,843] <wrn> cis_gateway: Unknown stream
GW [00:00:10.464,935] <inf> cis_gateway: Disconnected: 4B:D7:D6:29:40:2F (random) (reason 0x16)
GW [00:00:10.465,576] <inf> cis_gateway: Scanning successfully started
GW [00:00:10.861,907] <inf> cis_gateway: Connected: 44:EF:53:25:6B:96 (random)
GW [00:00:12.492,218] <err> cis_gateway: <<<<< security_changed_cb >>>>>
GW [00:00:12.492,218] <err> cis_gateway: <<<<< discover_sink >>>>>
GW [00:00:12.670,776] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:13.642,730] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:13.642,730] <wrn> cis_gateway: BT_AUDIO_LOCATION_FRONT_RIGHT 0x20005760
GW [00:00:13.642,730] <inf> cis_gateway: All headsets connected
GW [00:00:14.002,777] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:14.052,764] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:14.052,795] <wrn> cis_gateway: More than one sink endpoints found, ep idx 0 is used by default
GW [00:00:14.422,698] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:14.422,821] <err> cis_gateway: <<<<< discover_source >>>>>
GW [00:00:14.463,378] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:14.463,409] <inf> cis_gateway: RIGHT sink stream configured
GW [00:00:14.472,869] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:14.832,763] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:15.202,789] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:15.472,839] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:15.512,969] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:15.512,969] <inf> cis_gateway: RIGHT source stream configured
GW [00:00:15.573,303] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:15.573,333] <inf> cis_gateway: Enable stream 0x200023cc
GW [00:00:15.583,007] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:15.583,068] <inf> cis_gateway: Enable stream 0x200021ac
GW [00:00:15.613,250] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:15.633,239] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:15.633,636] <wrn> bt_conn: no transition connecting
GW [00:00:17.633,911] <err> cis_gateway: Failed to establish CIS, ret = -16
GW [00:00:17.653,320] <wrn> bt_hci_core: opcode 0x206f status 0x0c
GW [00:00:17.653,747] <wrn> bt_hci_core: opcode 0x206f status 0x12
GW [00:00:17.653,747] <inf> cis_gateway: Stream 0x200023cc stopped. Reason 13
GW [00:00:17.653,778] <wrn> cis_gateway: Unknown stream
GW [00:00:17.653,778] <inf> cis_gateway: Stream 0x200021ac stopped. Reason 13
GW [00:00:17.654,998] <wrn> cis_gateway: Unknown stream
GW [00:00:17.655,090] <inf> cis_gateway: Disconnected: 44:EF:53:25:6B:96 (random) (reason 0x16)
GW [00:00:17.655,731] <inf> cis_gateway: Scanning successfully started
GW [00:00:18.001,403] <inf> cis_gateway: Connected: 48:1A:C0:46:05:23 (random)
GW [00:00:19.722,412] <err> cis_gateway: <<<<< security_changed_cb >>>>>
GW [00:00:19.722,412] <err> cis_gateway: <<<<< discover_sink >>>>>
GW [00:00:19.901,489] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:20.742,919] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:20.742,919] <wrn> cis_gateway: BT_AUDIO_LOCATION_FRONT_RIGHT 0x20005760
GW [00:00:20.742,919] <inf> cis_gateway: All headsets connected
GW [00:00:21.082,977] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:21.132,965] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:21.132,995] <wrn> cis_gateway: More than one sink endpoints found, ep idx 0 is used by default
GW [00:00:21.482,910] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:21.483,001] <err> cis_gateway: <<<<< discover_source >>>>>
GW [00:00:21.513,580] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:21.513,580] <inf> cis_gateway: RIGHT sink stream configured
GW [00:00:21.514,739] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:21.872,955] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:22.162,994] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:22.413,024] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:22.453,155] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:22.453,155] <inf> cis_gateway: RIGHT source stream configured
GW [00:00:22.513,031] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:22.513,061] <inf> cis_gateway: Enable stream 0x200023cc
GW [00:00:22.513,519] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:22.513,580] <inf> cis_gateway: Enable stream 0x200021ac
GW [00:00:22.552,978] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:22.563,446] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:22.563,812] <wrn> bt_conn: no transition connecting
GW [00:00:24.564,117] <err> cis_gateway: Failed to establish CIS, ret = -16
GW [00:00:24.573,516] <wrn> bt_hci_core: opcode 0x206f status 0x0c
GW [00:00:24.573,944] <wrn> bt_hci_core: opcode 0x206f status 0x12
GW [00:00:24.573,944] <inf> cis_gateway: Stream 0x200023cc stopped. Reason 13
GW [00:00:24.573,944] <wrn> cis_gateway: Unknown stream
GW [00:00:24.573,974] <inf> cis_gateway: Stream 0x200021ac stopped. Reason 13
GW [00:00:24.575,195] <wrn> cis_gateway: Unknown stream
GW [00:00:24.575,286] <inf> cis_gateway: Disconnected: 48:1A:C0:46:05:23 (random) (reason 0x16)
GW [00:00:24.575,927] <inf> cis_gateway: Scanning successfully started
GW [00:00:25.193,725] <inf> cis_gateway: Connected: 7B:A7:91:0C:AE:5E (random)
GW [00:00:27.002,624] <err> cis_gateway: <<<<< security_changed_cb >>>>>
GW [00:00:27.002,624] <err> cis_gateway: <<<<< discover_sink >>>>>
GW [00:00:27.181,182] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:28.093,109] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:28.093,139] <wrn> cis_gateway: BT_AUDIO_LOCATION_FRONT_RIGHT 0x20005760
GW [00:00:28.093,139] <inf> cis_gateway: All headsets connected
GW [00:00:28.453,155] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:28.503,173] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:28.503,204] <wrn> cis_gateway: More than one sink endpoints found, ep idx 0 is used by default
GW [00:00:28.843,109] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:28.843,231] <err> cis_gateway: <<<<< discover_source >>>>>
GW [00:00:28.863,769] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:28.863,800] <inf> cis_gateway: RIGHT sink stream configured
GW [00:00:28.864,349] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:29.163,146] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:29.473,205] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:29.793,273] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:29.833,343] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:29.833,374] <inf> cis_gateway: RIGHT source stream configured
GW [00:00:29.893,707] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:29.893,737] <inf> cis_gateway: Enable stream 0x200023cc
GW [00:00:29.894,195] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:29.894,256] <inf> cis_gateway: Enable stream 0x200021ac
GW [00:00:29.933,197] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:29.943,634] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:29.944,030] <wrn> bt_conn: no transition connecting
GW [00:00:31.944,305] <err> cis_gateway: Failed to establish CIS, ret = -16
GW [00:00:31.954,101] <wrn> bt_hci_core: opcode 0x206f status 0x0c
GW [00:00:31.954,528] <wrn> bt_hci_core: opcode 0x206f status 0x12
GW [00:00:31.954,528] <inf> cis_gateway: Stream 0x200023cc stopped. Reason 13
GW [00:00:31.954,559] <wrn> cis_gateway: Unknown stream
GW [00:00:31.954,559] <inf> cis_gateway: Stream 0x200021ac stopped. Reason 13
GW [00:00:31.955,810] <wrn> cis_gateway: Unknown stream
GW [00:00:31.955,902] <inf> cis_gateway: Disconnected: 7B:A7:91:0C:AE:5E (random) (reason 0x16)
GW [00:00:31.956,542] <inf> cis_gateway: Scanning successfully started
GW [00:00:32.355,743] <inf> cis_gateway: Connected: 61:E7:90:D0:18:37 (random)
GW [00:00:33.892,791] <err> cis_gateway: <<<<< security_changed_cb >>>>>
GW [00:00:33.892,822] <err> cis_gateway: <<<<< discover_sink >>>>>
GW [00:00:34.071,380] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:35.243,316] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:35.243,347] <wrn> cis_gateway: BT_AUDIO_LOCATION_FRONT_RIGHT 0x20005760
GW [00:00:35.243,347] <inf> cis_gateway: All headsets connected
GW [00:00:35.583,374] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:35.623,382] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:35.623,413] <wrn> cis_gateway: More than one sink endpoints found, ep idx 0 is used by default
GW [00:00:35.933,319] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:35.933,410] <err> cis_gateway: <<<<< discover_source >>>>>
GW [00:00:35.973,968] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:35.973,999] <inf> cis_gateway: RIGHT sink stream configured
GW [00:00:35.983,489] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:36.313,354] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:36.603,393] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:36.863,433] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:36.903,564] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:36.903,564] <inf> cis_gateway: RIGHT source stream configured
GW [00:00:36.953,887] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:36.953,948] <inf> cis_gateway: Enable stream 0x200023cc
GW [00:00:36.963,592] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:36.963,653] <inf> cis_gateway: Enable stream 0x200021ac
GW [00:00:36.993,835] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:37.023,376] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:37.023,773] <wrn> bt_conn: no transition connecting
GW [00:00:39.024,047] <err> cis_gateway: Failed to establish CIS, ret = -16
GW [00:00:39.033,905] <wrn> bt_hci_core: opcode 0x206f status 0x0c
GW [00:00:39.034,332] <wrn> bt_hci_core: opcode 0x206f status 0x12
GW [00:00:39.034,362] <inf> cis_gateway: Stream 0x200023cc stopped. Reason 13
GW [00:00:39.034,362] <wrn> cis_gateway: Unknown stream
GW [00:00:39.034,362] <inf> cis_gateway: Stream 0x200021ac stopped. Reason 13
GW [00:00:39.035,583] <wrn> cis_gateway: Unknown stream
GW [00:00:39.035,705] <inf> cis_gateway: Disconnected: 61:E7:90:D0:18:37 (random) (reason 0x16)
GW [00:00:39.036,346] <inf> cis_gateway: Scanning successfully started
GW [00:00:39.435,546] <inf> cis_gateway: Connected: 58:44:76:E7:1F:C8 (random)
GW [00:00:41.153,015] <err> cis_gateway: <<<<< security_changed_cb >>>>>
GW [00:00:41.153,015] <err> cis_gateway: <<<<< discover_sink >>>>>
GW [00:00:41.421,569] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:42.353,515] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:42.353,546] <wrn> cis_gateway: BT_AUDIO_LOCATION_FRONT_RIGHT 0x20005760
GW [00:00:42.353,546] <inf> cis_gateway: All headsets connected
GW [00:00:42.703,552] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:42.743,560] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:42.743,591] <wrn> cis_gateway: More than one sink endpoints found, ep idx 0 is used by default
GW [00:00:43.113,494] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:43.113,616] <err> cis_gateway: <<<<< discover_source >>>>>
GW [00:00:43.163,726] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:43.163,757] <inf> cis_gateway: RIGHT sink stream configured
GW [00:00:43.164,276] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:43.473,541] <err> cis_gateway: <<<<< unicast_client_location_cb >>>>>
GW [00:00:43.763,610] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:44.023,651] <err> cis_gateway: <<<<< discover_source_cb >>>>>
GW [00:00:44.044,189] <err> cis_gateway: <<<<< stream_configured_cb >>>>>
GW [00:00:44.044,219] <inf> cis_gateway: RIGHT source stream configured
GW [00:00:44.064,086] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:44.064,147] <inf> cis_gateway: Enable stream 0x200023cc
GW [00:00:44.064,605] <err> cis_gateway: <<<<< stream_qos_set_cb >>>>>
GW [00:00:44.064,636] <inf> cis_gateway: Enable stream 0x200021ac
GW [00:00:44.074,127] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:44.084,045] <err> cis_gateway: <<<<< stream_enabled_cb >>>>>
GW [00:00:44.084,411] <wrn> bt_conn: no transition connecting
GW [00:00:46.084,686] <err> cis_gateway: Failed to establish CIS, ret = -16
GW [00:00:46.094,116] <wrn> bt_hci_core: opcode 0x206f status 0x0c
GW [00:00:46.094,543] <wrn> bt_hci_core: opcode 0x206f status 0x12
GW [00:00:46.094,543] <inf> cis_gateway: Stream 0x200023cc stopped. Reason 13
GW [00:00:46.094,543] <wrn> cis_gateway: Unknown stream
GW [00:00:46.094,573] <inf> cis_gateway: Stream 0x200021ac stopped. Reason 13
GW [00:00:46.095,794] <wrn> cis_gateway: Unknown stream
GW [00:00:46.095,886] <inf> cis_gateway: Disconnected: 58:44:76:E7:1F:C8 (random) (reason 0x16)
GW [00:00:46.096,527] <inf> cis_gateway: Scanning successfully started
GW [00:00:46.213,775] <inf> cis_gateway: Connected: 40:EB:E0:AD:11:02 (random)
GW [00:00:47.311,126] <wrn> cis_gateway: Unknown stream
GW [00:00:47.311,218] <inf> cis_gateway: Disconnected: 60:20:E9:4A:5E:67 (random) (reason 0x13)
GW [00:00:47.311,889] <inf> cis_gateway: Scanning successfully started
GW [00:00:47.763,641] <err> cis_gateway: <<<<< security_changed_cb >>>>>
GW [00:00:47.763,641] <err> cis_gateway: <<<<< discover_sink >>>>>
GW [00:00:47.843,658] <err> cis_gateway: <<<<< discover_sink_cb >>>>>
GW [00:00:47.843,658] <err> cis_gateway: Discovery failed: 14
GW [00:00:47.843,811] <inf> cis_gateway: Disconnected: 40:EB:E0:AD:11:02 (random) (reason 0x13)
GW [00:00:47.843,811] <wrn> cis_gateway: Connection not found
GW [00:00:47.843,841] <wrn> cis_gateway: Unknown connection
GW [00:00:47.843,841] <inf> cis_gateway: Scanning successfully started

Problem #3 - Source audio not always acquired

The next issue that I have seen is if you connect to the headset successfully, the first time the connection is made, the source (headset microphone) audio will play on the headphone jack every time. The issue comes when you put the headset back in the case and close the lid, then re-open and take the headset out. The next successful connection will have a 50% chance of the microphone audio playing on the headphone jack. This 50% chance of source audio working happens every time you put the headphones back in the case and take them out again. 

One note: I have also tested this on a non-audio DK, with the source audio being fed back into the headset sink. For this reason, I don't think the issue has to do with the I2S or HW codec etc.

Lastly, it looks like the audio in data is still being received since the callback for Rx data is still being called.

I have attached an example project. It is the LE audio demo code with minor modifications. Search for <Modified> in the code to see what I modified. The modifications were only made in prj.conf and le_audio_cis_gateway.c

nrf2_4_0_AudioDemo.zip

[Karl Ylvisaker]

Hello again,

We have not yet performed any tests with the Galaxy buds pro 2 since the nRF Connect SDK v2.4 release, but we will schedule some next week to take a closer look at the issues you have reported here. In the meantime, I have a few suggestions you could try on your own, along with some additional questions.

The demo connects successfully out of the box to the headphones, with some modifications to the prj.conf file, using the nRF5340 Audio DK. For my project needs, I have both source and sink enabled via CONFIG_STREAM_BIDIRECTIONAL.

We have not yet tested using bidirectional streams with the galaxy buds pro 2 before. Does everything work as expected when you run the same test without the CONFIG_STREAM_BIDIRECTIONAL set?

Regarding Problem #1:
This behavior was indeed a known issue with the 3330 controller, but it was resolved before the v3349 release, so this is a very interesting report.
I will need to discuss this some more with the team, and we will test this specifically next week.

Regarding Problem #2:
When we tested with the Galaxy buds pro 2 before we found that we had to make these modifications to our gateway device to have the most stable connection to the Galaxy buds pro 2:
- The presentation delay must be set to 40 ms
- The ACL connection interval should be 45 ms
- The maximum number of retransmissions we should use is 2
- There should be a small delay between the establishment of the two CISs

Please make sure that you are using these configuration in your test, and see if that improves the stability of the connection.

Regarding Problem #3:
During our last round of testing with the Galaxy Buds Pro 2 we saw that there was some issue with the bonding to the earbuds, which perhaps could be related to what you are seeing here.
Is the ACL to the earbuds terminated when they are put in the case?
You mention that it works 50% of the time, could you elaborate on the behavior on the other 50% of the time when it is not working?
It would also be great if you could capture a sniffer trace of these two scenarios (just of the link establishments, not of the ISO parts), so that I could check if there any indication of what goes wrong when it does.

Again I would like to thank you for the detailed report, and I will keep you updated on any news from our own testing of the Galaxy Buds Pro 2 next week :) 

Best regards,
Karl

[ksmith197]

For the bonding issue, it looks like if you keep the left headset in the case then bond with the right headset only, you can reboot the processor and it at least attempts to connect to the right headset repeatably. Once the left is bonded though, it won't connect to either headset.

This also works the other way around. If you keep the right headset in the case then only bond to the left, it attempts to connect.

Interestingly, if you set CONFIG_BT_MAX_PAIRED=3, then it will attempt to connect as well. It seems once the bonds are full it doesn't even try to scan.

Attempted connection:

[00:00:05.112,945] <err> cis_gateway: ConnectedCb: <<<<< ConnectedCb >>>>>
[00:00:05.113,037] <inf> cis_gateway: ConnectedCb: Connected: 40:5E:F6:5A:C4:9E (public)
[00:00:05.113,098] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:05.113,128] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:05.113,128] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:05.113,159] <dbg> bt_conn: bt_conn_process_tx: conn 0x200052c0
[00:00:05.113,159] <dbg> bt_conn: send_buf: conn 0x200052c0 buf 0x2001b9d8 len 7
[00:00:05.113,189] <dbg> bt_conn: send_buf: send single
[00:00:05.113,189] <dbg> bt_conn: do_send_frag: conn 0x200052c0 buf 0x2001b9d8 len 7 flags 0x02
[00:00:05.113,250] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:05.113,250] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:05.113,250] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:05.113,403] <dbg> bt_keys: bt_keys_find: type 32 40:5E:F6:5A:C4:9E (public)
[00:00:05.113,525] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:05.113,525] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:05.113,525] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:05.113,769] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:05.113,769] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:05.113,800] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:05.114,410] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:05.114,410] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:05.114,440] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:05.114,440] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:05.114,440] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:05.225,799] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:05.225,830] <dbg> bt_conn: tx_complete_work: conn 0x200052c0
[00:00:05.225,830] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:05.225,830] <dbg> bt_conn: tx_notify: tx 0x2000ada8 cb 0x744ed user_data 0x2000aed8
[00:00:05.225,921] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:05.225,982] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:05.225,982] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:05.226,226] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:05.226,257] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:05.226,257] <dbg> bt_conn: bt_conn_recv: handle 0 len 13 flags 02
[00:00:05.226,257] <dbg> bt_conn: bt_acl_recv: First, len 13 final 9
[00:00:05.226,287] <dbg> bt_conn: bt_acl_recv: Successfully parsed 13 byte L2CAP packet
[00:00:05.226,318] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 9 cb 0x74525 user_data 0x2000aeec
[00:00:05.226,348] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:05.226,379] <dbg> bt_conn: bt_conn_process_tx: conn 0x200052c0
[00:00:05.226,379] <dbg> bt_conn: send_buf: conn 0x200052c0 buf 0x2001b9d8 len 9
[00:00:05.226,409] <dbg> bt_conn: send_buf: send single
[00:00:05.226,440] <dbg> bt_conn: do_send_frag: conn 0x200052c0 buf 0x2001b9d8 len 9 flags 0x02
[00:00:05.226,470] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:05.226,470] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:05.226,501] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:05.405,761] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:05.405,792] <err> cis_gateway: SecurityChangedCb: <<<<< SecurityChangedCb >>>>>
[00:00:05.405,792] <err> cis_gateway: SecurityChangedCb: Security failed: level 1 err 2
[00:00:05.405,822] <wrn> cis_gateway: ChannelIndexGet: Connection not found 0x200052c0
[00:00:05.405,822] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:05.495,788] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:05.495,819] <dbg> bt_conn: tx_complete_work: conn 0x200052c0
[00:00:05.495,819] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:05.495,819] <dbg> bt_conn: tx_notify: tx 0x2000adb8 cb 0x74525 user_data 0x2000aeec
[00:00:05.495,880] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:05.495,941] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:05.495,941] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:05.495,971] <dbg> bt_conn: bt_conn_recv: handle 0 len 7 flags 02
[00:00:05.495,971] <dbg> bt_conn: bt_acl_recv: First, len 7 final 3
[00:00:05.495,971] <dbg> bt_conn: bt_acl_recv: Successfully parsed 7 byte L2CAP packet
[00:00:05.496,002] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:05.586,212] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:05.586,212] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:05.586,242] <dbg> bt_conn: bt_conn_recv: handle 0 len 11 flags 02
[00:00:05.586,242] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:00:05.586,242] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:05.586,303] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 9 cb 0x74525 user_data 0x2000af14
[00:00:05.586,334] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:05.586,364] <dbg> bt_conn: bt_conn_process_tx: conn 0x200052c0
[00:00:05.586,364] <dbg> bt_conn: send_buf: conn 0x200052c0 buf 0x2001b9d8 len 9
[00:00:05.586,395] <dbg> bt_conn: send_buf: send single
[00:00:05.586,395] <dbg> bt_conn: do_send_frag: conn 0x200052c0 buf 0x2001b9d8 len 9 flags 0x02
[00:00:05.586,425] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:05.586,456] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:05.586,456] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:05.675,781] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:05.675,811] <dbg> bt_conn: tx_complete_work: conn 0x200052c0
[00:00:05.675,811] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:05.675,811] <dbg> bt_conn: tx_notify: tx 0x2000adc8 cb 0x74525 user_data 0x2000af14
[00:00:05.675,872] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:05.765,777] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:05.765,777] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:05.765,808] <dbg> bt_conn: bt_conn_recv: handle 0 len 11 flags 02
[00:00:05.765,808] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:00:05.765,808] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:05.765,869] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 27 cb 0x74525 user_data 0x2000af28
[00:00:05.765,899] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:05.765,930] <dbg> bt_conn: bt_conn_process_tx: conn 0x200052c0
[00:00:05.765,930] <dbg> bt_conn: send_buf: conn 0x200052c0 buf 0x2001b9d8 len 27
[00:00:05.765,930] <dbg> bt_conn: send_buf: send single
[00:00:05.765,960] <dbg> bt_conn: do_send_frag: conn 0x200052c0 buf 0x2001b9d8 len 27 flags 0x02
[00:00:05.765,991] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:05.765,991] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:05.766,021] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:05.855,834] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:05.855,865] <dbg> bt_conn: tx_complete_work: conn 0x200052c0
[00:00:05.855,895] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:05.855,895] <dbg> bt_conn: tx_notify: tx 0x2000add8 cb 0x74525 user_data 0x2000af28
[00:00:05.855,957] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:05.945,770] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:05.945,800] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:05.945,800] <dbg> bt_conn: bt_conn_recv: handle 0 len 11 flags 02
[00:00:05.945,831] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:00:05.945,831] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:05.945,892] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 9 cb 0x74525 user_data 0x2000af50
[00:00:05.945,922] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:05.945,953] <dbg> bt_conn: bt_conn_process_tx: conn 0x200052c0
[00:00:05.945,953] <dbg> bt_conn: send_buf: conn 0x200052c0 buf 0x2001b9d8 len 9
[00:00:05.945,953] <dbg> bt_conn: send_buf: send single
[00:00:05.945,983] <dbg> bt_conn: do_send_frag: conn 0x200052c0 buf 0x2001b9d8 len 9 flags 0x02
[00:00:05.946,014] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:05.946,014] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:05.946,044] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:06.023,803] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:06.023,834] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:06.023,834] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:06.035,766] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:06.035,797] <dbg> bt_conn: tx_complete_work: conn 0x200052c0
[00:00:06.035,797] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:06.035,797] <dbg> bt_conn: tx_notify: tx 0x2000ade8 cb 0x74525 user_data 0x2000af50
[00:00:06.035,858] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:06.125,762] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:06.125,793] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:06.125,793] <dbg> bt_conn: bt_conn_recv: handle 0 len 9 flags 02
[00:00:06.125,793] <dbg> bt_conn: bt_acl_recv: First, len 9 final 5
[00:00:06.125,823] <dbg> bt_conn: bt_acl_recv: Successfully parsed 9 byte L2CAP packet
[00:00:06.125,854] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 38 cb 0x74525 user_data 0x2000af64
[00:00:06.125,885] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:06.125,915] <dbg> bt_conn: bt_conn_process_tx: conn 0x200052c0
[00:00:06.125,915] <dbg> bt_conn: send_buf: conn 0x200052c0 buf 0x2001b9d8 len 38
[00:00:06.125,915] <dbg> bt_conn: send_buf: send single
[00:00:06.125,946] <dbg> bt_conn: do_send_frag: conn 0x200052c0 buf 0x2001b9d8 len 38 flags 0x02
[00:00:06.125,976] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:06.125,976] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:06.126,007] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:06.216,278] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:06.216,308] <dbg> bt_conn: tx_complete_work: conn 0x200052c0
[00:00:06.216,308] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:06.216,339] <dbg> bt_conn: tx_notify: tx 0x2000adf8 cb 0x74525 user_data 0x2000af64
[00:00:06.216,369] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:06.305,786] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:06.305,816] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:06.305,816] <dbg> bt_conn: bt_conn_recv: handle 0 len 13 flags 02
[00:00:06.305,816] <dbg> bt_conn: bt_acl_recv: First, len 13 final 9
[00:00:06.305,847] <dbg> bt_conn: bt_acl_recv: Successfully parsed 13 byte L2CAP packet
[00:00:06.305,908] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 9 cb 0x74525 user_data 0x2000af8c
[00:00:06.305,938] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:06.305,938] <dbg> bt_conn: bt_conn_process_tx: conn 0x200052c0
[00:00:06.305,969] <dbg> bt_conn: send_buf: conn 0x200052c0 buf 0x2001b9d8 len 9
[00:00:06.305,969] <dbg> bt_conn: send_buf: send single
[00:00:06.305,969] <dbg> bt_conn: do_send_frag: conn 0x200052c0 buf 0x2001b9d8 len 9 flags 0x02
[00:00:06.306,030] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:06.306,030] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:06.306,030] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:06.395,782] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:06.395,812] <dbg> bt_conn: tx_complete_work: conn 0x200052c0
[00:00:06.395,812] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:06.395,812] <dbg> bt_conn: tx_notify: tx 0x2000ae08 cb 0x74525 user_data 0x2000af8c
[00:00:06.395,874] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:06.485,778] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:06.485,778] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:06.485,809] <dbg> bt_conn: bt_conn_recv: handle 0 len 8 flags 02
[00:00:06.485,809] <dbg> bt_conn: bt_acl_recv: First, len 8 final 4
[00:00:06.485,809] <dbg> bt_conn: bt_acl_recv: Successfully parsed 8 byte L2CAP packet
[00:00:06.485,870] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 5 cb 0x74525 user_data 0x2000afa0
[00:00:06.485,900] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:06.485,931] <dbg> bt_conn: bt_conn_process_tx: conn 0x200052c0
[00:00:06.485,931] <dbg> bt_conn: send_buf: conn 0x200052c0 buf 0x2001b9d8 len 5
[00:00:06.485,931] <dbg> bt_conn: send_buf: send single
[00:00:06.485,961] <dbg> bt_conn: do_send_frag: conn 0x200052c0 buf 0x2001b9d8 len 5 flags 0x02
[00:00:06.485,992] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:06.485,992] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:06.486,022] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:06.575,744] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:06.575,775] <dbg> bt_conn: tx_complete_work: conn 0x200052c0
[00:00:06.575,775] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:06.575,805] <dbg> bt_conn: tx_notify: tx 0x2000ae18 cb 0x74525 user_data 0x2000afa0
[00:00:06.575,836] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:06.755,767] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:06.755,798] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:06.755,828] <dbg> bt_conn: bt_conn_recv: handle 0 len 9 flags 02
[00:00:06.755,828] <dbg> bt_conn: bt_acl_recv: First, len 9 final 5
[00:00:06.755,828] <dbg> bt_conn: bt_acl_recv: Successfully parsed 9 byte L2CAP packet
[00:00:06.755,950] <dbg> bt_keys: bt_keys_find_addr: 40:5E:F6:5A:C4:9E (public)
[00:00:06.756,408] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 5 cb 0x74525 user_data 0x2000afb4
[00:00:06.756,439] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:06.756,469] <dbg> bt_conn: bt_conn_process_tx: conn 0x200052c0
[00:00:06.756,469] <dbg> bt_conn: send_buf: conn 0x200052c0 buf 0x2001b9d8 len 5
[00:00:06.756,469] <dbg> bt_conn: send_buf: send single
[00:00:06.756,500] <dbg> bt_conn: do_send_frag: conn 0x200052c0 buf 0x2001b9d8 len 5 flags 0x02
[00:00:06.756,530] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:06.756,530] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:06.756,561] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:06.845,764] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:06.845,794] <dbg> bt_conn: tx_complete_work: conn 0x200052c0
[00:00:06.845,794] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:06.845,825] <dbg> bt_conn: tx_notify: tx 0x2000ae28 cb 0x74525 user_data 0x2000afb4
[00:00:06.845,855] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:06.935,760] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:06.935,791] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:06.935,791] <dbg> bt_conn: bt_conn_recv: handle 0 len 7 flags 02
[00:00:06.935,791] <dbg> bt_conn: bt_acl_recv: First, len 7 final 3
[00:00:06.935,821] <dbg> bt_conn: bt_acl_recv: Successfully parsed 7 byte L2CAP packet
[00:00:06.935,852] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 21 cb 0x74525 user_data 0x2000aed8
[00:00:06.935,882] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:06.935,913] <dbg> bt_conn: bt_conn_process_tx: conn 0x200052c0
[00:00:06.935,913] <dbg> bt_conn: send_buf: conn 0x200052c0 buf 0x2001b9d8 len 21
[00:00:06.935,913] <dbg> bt_conn: send_buf: send single
[00:00:06.935,943] <dbg> bt_conn: do_send_frag: conn 0x200052c0 buf 0x2001b9d8 len 21 flags 0x02
[00:00:06.935,974] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:06.936,004] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:06.936,004] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:07.023,803] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:07.023,803] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:07.023,834] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:07.115,844] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:07.115,844] <dbg> bt_conn: tx_complete_work: conn 0x200052c0
[00:00:07.115,875] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:07.115,875] <dbg> bt_conn: tx_notify: tx 0x2000ae38 cb 0x74525 user_data 0x2000aed8
[00:00:07.115,936] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:07.385,864] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:07.385,894] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:07.385,955] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:07.385,955] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:07.385,955] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:08.015,747] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:08.015,747] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:08.023,773] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:08.023,803] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:08.023,803] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:08.025,787] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:08.025,817] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:08.025,817] <dbg> bt_conn: bt_conn_recv: handle 0 len 11 flags 02
[00:00:08.025,848] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:00:08.025,848] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:08.025,909] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 9 cb 0x74525 user_data 0x2000aeec
[00:00:08.025,909] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:08.025,939] <dbg> bt_conn: bt_conn_process_tx: conn 0x200052c0
[00:00:08.025,970] <dbg> bt_conn: send_buf: conn 0x200052c0 buf 0x2001b9d8 len 9
[00:00:08.025,970] <dbg> bt_conn: send_buf: send single
[00:00:08.025,970] <dbg> bt_conn: do_send_frag: conn 0x200052c0 buf 0x2001b9d8 len 9 flags 0x02
[00:00:08.026,031] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:08.026,031] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:08.026,031] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:08.035,797] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:08.035,827] <dbg> bt_conn: tx_complete_work: conn 0x200052c0
[00:00:08.035,858] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:08.035,858] <dbg> bt_conn: tx_notify: tx 0x2000ae48 cb 0x74525 user_data 0x2000aeec
[00:00:08.035,919] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:08.035,980] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:08.035,980] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:08.055,786] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:08.055,816] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:08.055,816] <dbg> bt_conn: bt_conn_recv: handle 0 len 11 flags 02
[00:00:08.055,816] <dbg> bt_conn: bt_acl_recv: First, len 11 final 7
[00:00:08.055,847] <dbg> bt_conn: bt_acl_recv: Successfully parsed 11 byte L2CAP packet
[00:00:08.055,908] <dbg> bt_conn: bt_conn_send_cb: conn handle 0 buf len 9 cb 0x74525 user_data 0x2000af14
[00:00:08.055,938] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:08.055,938] <dbg> bt_conn: bt_conn_process_tx: conn 0x200052c0
[00:00:08.055,969] <dbg> bt_conn: send_buf: conn 0x200052c0 buf 0x2001b9d8 len 9
[00:00:08.055,969] <dbg> bt_conn: send_buf: send single
[00:00:08.055,969] <dbg> bt_conn: do_send_frag: conn 0x200052c0 buf 0x2001b9d8 len 9 flags 0x02
[00:00:08.056,030] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:08.056,030] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:08.056,030] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:08.065,795] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:08.065,826] <dbg> bt_conn: tx_complete_work: conn 0x200052c0
[00:00:08.065,826] <dbg> bt_conn: tx_notify: conn 0x200052c0
[00:00:08.065,826] <dbg> bt_conn: tx_notify: tx 0x2000ae58 cb 0x74525 user_data 0x2000af14
[00:00:08.065,887] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:08.125,854] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:08.125,885] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:08.125,946] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:08.125,976] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:08.125,976] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:08.195,739] <dbg> bt_conn: bt_conn_ref: handle 0 ref 2 -> 3
[00:00:08.195,739] <dbg> bt_conn: bt_conn_unref: handle 0 ref 3 -> 2
[00:00:09.023,773] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:09.023,803] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:09.023,803] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:10.023,773] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:10.023,803] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:10.023,803] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:11.023,773] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:11.023,803] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:11.023,803] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:12.023,773] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:12.023,803] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:12.023,803] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:13.023,773] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:13.023,803] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:13.023,803] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:14.023,773] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:14.023,803] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:14.023,803] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:15.023,773] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:15.023,803] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:15.023,803] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:16.023,773] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:16.023,803] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:16.023,803] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:17.023,773] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:17.023,803] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:17.023,803] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:18.023,773] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:18.023,803] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:18.023,803] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:19.023,773] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:19.023,803] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:19.023,803] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:20.023,773] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:20.023,803] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:20.023,803] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:21.023,773] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:21.023,803] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:21.023,803] <dbg> bt_conn: conn_prepare_events: wait on host fifo
[00:00:22.023,773] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:22.023,803] <dbg> bt_conn: conn_prepare_events: Adding conn 0x200052c0 to poll list
[00:00:22.023,803] <dbg> bt_conn: conn_prepare_events: wait on host fifo

When both headsets are connected though, it hangs on bt_conn_prepare_events

[00:00:00.180,084] <err> cis_gateway: LeHeadset_AudioEnable: <<<<< le_audio_enable >>>>>
[00:00:00.180,114] <err> cis_gateway: Initialize: <<<<< Initialize >>>>>
[00:00:00.180,267] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:00.180,694] <err> cis_gateway: BondCheck: <<<<< BondCheck >>>>>
[00:00:00.180,786] <wrn> cis_gateway: BondCheck: Stored bonding found: 40:5E:F6:5A:C4:9E (public)
[00:00:00.180,786] <err> cis_gateway: BondCheck: <<<<< BondCheck >>>>>
[00:00:00.180,877] <wrn> cis_gateway: BondCheck: Stored bonding found: 40:5E:F6:5A:BF:9D (public)
[00:00:00.180,877] <inf> cis_gateway: BleAclStartScan: All bonded slots filled, will not accept new devices
[00:00:00.181,915] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:00.182,159] <inf> bt_id: bt_id_set_private_addr: RPA: 4A:02:DF:3E:7C:CB
[00:00:00.182,220] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:00.182,464] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:00.182,769] <inf> cis_gateway: BleAclStartScan: Scanning successfully started
[00:00:00.182,800] <err> ExampleUsageDrv: Init: Example Usage Start
[00:00:00.182,861] <inf> app_event_manager: log_module_state_event: e:module_state_event module:main state:READY
[00:00:01.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:02.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:03.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:04.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:05.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:06.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:07.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:08.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:09.022,827] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:10.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:11.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:12.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:13.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:14.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:15.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:16.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:17.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:18.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:19.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:20.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:21.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:22.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:23.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:24.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:25.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:26.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:27.022,827] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:28.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:29.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:30.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:31.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:32.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:33.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:34.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:35.022,827] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:36.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:37.022,796] <dbg> bt_conn: bt_conn_prepare_events:
[00:00:38.022,796] <dbg> bt_conn: bt_conn_prepare_events:

[ksmith197]

We can't provide a pre-release version of the controller. You will have to wait for the official release.

We also don't have a guarantee for a fix because of the descriptions not matching (as Karl pointed out).

OK no problem. The attached zip file should provide the controller crash fail condition for your testing. Thanks anyway though

[ksmith197]

Also, another issue, we have tried implementing 8 Khz LC3 audio, which looks to be correct, except that the connection drops immediately after starting streaming.

What is the progress on the crash issue? We are going on 3 weeks and I haven't heard any news that you have replicated the crash issue.

[Maria Gilje]

Hello!

Sorry about the delay, and thank you for your patience.

ksmith197 said:

Also, another issue, we have tried implementing 8 Khz LC3 audio, which looks to be correct, except that the connection drops immediately after starting streaming.

Based on what I can see this should be supported. But I will ask the LE Audio experts to make sure.

ksmith197 said:

What is the progress on the crash issue? We are going on 3 weeks and I haven't heard any news that you have replicated the crash issue.

We still haven't been able to reproduce the crash, so we need some more help from you. In addition to the crash problem

About problem #1:

Our tester is back in office and has tried to replicate the crash. He has not been able to do this though.

We want to be sure that his environment is the same as yours. Could you please check that the correct toolchain is chosen when you are building your project? For NCS v2.3.0 this should be located in ncs/toolchains/v2.3.0 if you have an automatic install and the zephyr-sdk version should be 0.15.2.

---

For problem #2:

Our tester has not seen the disconnection happen.

---

Now to problem #3:

Samsung earbuds will not work without MCS in the gateway. MCS with bidirectional mode is not supported by our solution now.

Something to look out for is that if you pause the stream before the earbuds are disconnected, the state of the stream will be different from the expectations of the connection. After reconnection the earbuds will request the streams to play, but the gateway will only know how to enable.

Our main tester had some time to prepare modifications you can use to test:

In prj.conf add these configs:

CONFIG_AUDIO_SOURCE_I2S=y
CONFIG_BLE_ACL_CONN_INTERVAL=36
CONFIG_BT_AUDIO_PRESENTATION_DELAY_US=40000
CONFIG_BT_AUDIO_MAX_TRANSPORT_LATENCY_MS=100
CONFIG_BT_DEVICE_NAME="Galaxy Buds2 Pro"
CONFIG_BT_LOG_SNIFFER_INFO=y
CONFIG_BT_BONDABLE=n
CONFIG_STREAM_BIDIRECTIONAL=y

Best regards,

Maria

[Maria Gilje]

I included some incomplete and irrelevant information in my last post. Sorry about that.

Corrections and additions below.

Maria Gilje said:

We want to be sure that his environment is the same as yours. Could you please check that the correct toolchain is chosen when you are building your project? For NCS v2.3.0 this should be located in ncs/toolchains/v2.3.0 if you have an automatic install and the zephyr-sdk version should be 0.15.2.

You are using NCS 2.4.0 of course, so here is the relevant information:

For NCS v2.4.0 this should be located in ncs/toolchains/31f4403e35 if you have an automatic install and the zephyr-sdk version should be 0.16.0.

Maria Gilje said:

Our main tester had some time to prepare modifications you can use to test:

I only included the prj.conf additions, but le_audio_cis_gateway needs modifications as well.

Comment out:

 static void bond_check(const struct bt_bond_info *info, void *user_data)
 {
 	char addr_buf[BT_ADDR_LE_STR_LEN];
@@ -1008,6 +1009,7 @@ static void bond_check(const struct bt_bond_info *info, void *user_data)
 	LOG_DBG("Stored bonding found: %s", addr_buf);
 	bonded_num++;
 }

and

 	bt_foreach_bond(BT_ID_DEFAULT, bond_check, NULL);
 
 	if (bonded_num >= CONFIG_BT_MAX_PAIRED) {
 		LOG_INF("All bonded slots filled, will not accept new devices");
 	}

Replace

if (bonded_num < CONFIG_BT_MAX_PAIRED) {

          ad_parse(p_ad, addr);

      }

with

+       ad_parse(p_ad, addr);

Add

if (ep_state_check(headsets[AUDIO_CH_L].source_stream.ep,
            BT_BAP_EP_STATE_QOS_CONFIGURED)) {
		ret = bt_bap_stream_enable(&headsets[AUDIO_CH_L].source_stream,
					   lc3_preset_source.codec.meta,
					   lc3_preset_source.codec.meta_count);

	if (ret) {
		LOG_WRN("Failed to enable left stream");
	}
}

as a third if-statement within le_audio_play_pause_cb(bool play) if(play).

Best regards,

Maria

[ksmith197]

Hello, thanks for the reply,

Yes, I am using version 2.4.0 of the SDK. I moved the install to a different directory but it is an install from the nRF Connect application, automatic install. My zephyr-sdk is version 0.16.0

Problem #1:

Have you tried using the supplied project zip file in the original post? You also need to make sure the headset connects right first then left to see the crash. It happens nearly every time.

Problem #3:

Just to make sure, the above bond code modifications le_audio_play_pause_cb are related to problem 3, correct? Ok I will try to test this today or tomorrow. Thank you! :)

[Maria Gilje]

Problem #1:

ksmith197 said:

Have you tried using the supplied project zip file in the original post? You also need to make sure the headset connects right first then left to see the crash. It happens nearly every time.

Yes, our tester is using your code from the .zip. He has tried many times with no controller crash. I don't know if it is because the left bud connects first every time, so I will ask about this to make sure.

ksmith197 said:

I have a zip file attached to the post with a failing setup. Search for <Modified> in the code to see what I modified. In the code it connects, then checks if right or left via location like you described. If right first, disconnect and try again.

Is this how you test that the crash happens every time the right bud connects before the left?

Since our tester can't reproduce I wonder if there is something we can do to modify the test setup. Please let me know if you have found a way to get the right earbud to connect first more frequently.

Problem #3:

ksmith197 said:

Just to make sure, the above bond code modifications le_audio_play_pause_cb are related to problem 3, correct? Ok I will try to test this today or tomorrow. Thank you! :)

Yes, all of the proposed code changes from my last two replies are related to problem #3.

Best regards,

Maria

[ksmith197]

Hey sorry haven't had a chance to test out the snipit of code you provided just yet. 

Problem #1

Yes right must connect first to cause the issue. Also, if you are using the provided code, make sure this #define is set to false. The fix basically forces left to connect before right, in which case you will not see the controller crash. If false, the original code is used, which can connect right before left.

#define HACK_FIXES_ENABLED (false)

Maria Gilje said:

Is this how you test that the crash happens every time the right bud connects before the left?

Since our tester can't reproduce I wonder if there is something we can do to modify the test setup. Please let me know if you have found a way to get the right earbud to connect first more frequently.

The <Modified> shows where i have made changes to the original code. The only places <Modified> have been added are to fix Problem #1 and to print more information to console. The additional code forces the headsets to connect left before right, preventing the crash issue. If you disable the <Modified> code via the above macro, it will connect randomly left or right headset first.

Maria Gilje said:

Yes, all of the proposed code changes from my last two replies are related to problem #3.

Great thanks, i'm working on some other issues at the moment but will come back to this ASAP.

[Maria Gilje]

Hello,

ksmith197 said:

Problem #1

Yes right must connect first to cause the issue. Also, if you are using the provided code, make sure this #define is set to false. The fix basically forces left to connect before right, in which case you will not see the controller crash. If false, the original code is used, which can connect right before left.

#define HACK_FIXES_ENABLED (false)

This was the setup for the tests done, but still our tester did not experience the controller crash.

ksmith197 said:

Great thanks, i'm working on some other issues at the moment but will come back to this ASAP.

Take the time you need and please let me know when you have tested.

BR,

Maria

[Maria Gilje]

Hi again,

I'm just letting you know that controller v3357 has been merged to the main branch of NCS now.

BR,

Maria

[ClinicalAudio]

Hi, just wandering if there was any further achievement on this?

I'm not looking for bidirectional, but whether the CONFIG_STREAM_BIDIRECTIONAL flag is set or not I still see the same behaviour.

If I take a vanilla nrf5340_audio example, add proj.conf flags as recommended above but I see near identical behaviour to ksmith:

If I present both buds to pair, Left usually connects and is stable, Right attempts to connect but fails.  I can play audio through left - connection appears stable.  If Right does connect first, Left does not connect and I get a stream of errors: <wrn> audio_datapath: In I2S TX underrun condition, total: 5000.  This counts up and at about 30s the audio stream to the right is lost.

If I "hide" the right bud in the case, Left connects as above and the connection is stable

If I "hide" the left bud in the case, Right connects and the audio stream is stable for between a few tens of seconds to single-digit minutes.

I'm working with SDK v2.4.1 

Many thanks