Regarding the behavior of link

[tommy]

In the link process between Central and Peripheral,

sometimes Link processing does not work correctly and the following log output:

. cis_gateway: Discovery failed: 14

 Please find the attached ppt.

Could you specify what might cause this based on the Log?

This problem happens in SDK 2.3.0, and improved in 2.7.0.

Link err.pptx 

We have gotton the logs by EVK.
Is there anything you think might be the cause?

[dejans]

Hi,

Which application(s) do you use on your devices?

We have gotton the logs by EVK.

Do you use nrf5340_audio-dk on both ends? How many headsets do you use?

This problem happens in SDK 2.3.0, and improved in 2.7.0.

Is your log shown for NCS v2.3.0 or for NCS v2.7.0?

Please provide full logs from all devices by clicking on Insert -> Image/video/file -> Upload.

Best regards,
Dejan

[tommy]

>Do you use nrf5340_audio-dk on both ends? How many headsets do you use?
Yes for both ends.

We use 1 headset vs 1 gateway.

>Is your log shown for NCS v2.3.0 or for NCS v2.7.0?

Please find the attached files.
These are the Logs gotten by NCS v2.3.0.

Fullscreen SDK2.3.0_FailureLog_GW.txt Download

GW [00:13:16.236,083] <wrn> bt_hci_core: opcode 0x206f status 0x0c
GW [00:13:16.236,297] <wrn> bt_hci_core: opcode 0x206f status 0x12
GW [00:13:16.236,297] <inf> cis_gateway: Stream 0x200046ec stopped
GW [00:13:16.237,182] <inf> cis_gateway: Disconnected: E7:F7:B5:23:BC:DE (random) (reason 0x08)
GW [00:13:16.237,274] <inf> cis_gateway: Stored bonding found: E7:F7:B5:23:BC:DE (random)
GW [00:13:16.237,274] <inf> cis_gateway: Scanning successfully started
GW [00:13:16.241,912] <wrn> streamctrl: Problem with sending LE audio data, ret: -140
GW [00:13:16.488,677] <inf> cis_gateway: Connected: E7:F7:B5:23:BC:DE (random)
GW [00:13:16.933,319] <inf> cis_gateway: Security changed: level 2
GW [00:13:17.834,045] <err> cis_gateway: Discovery failed: 14
GW [00:13:18.433,380] <inf> cis_gateway: Stored bonding found: E7:F7:B5:23:BC:DE (random)
GW [00:13:18.433,959] <inf> cis_gateway: Scanning successfully started
GW [00:13:19.033,447] <err> cis_gateway: Discovery failed: 14
GW [00:13:19.835,510] <wrn> cis_gateway: No sink endpoints found

Fullscreen SDK2.3.0_FailureLog_HL.txt Download

*** Booting Zephyr OS build v3.2.99-ncs2 ***
I: Starting bootloader
I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Boot source: none
I: Swap type: none
I: Bootloader chainload address offset: 0xc000
*** Booting Zephyr OS build v3.2.99-ncs2 ***
HL [00:00:00.006,439] <inf> fw_info:
         nRF5340 Audio nRF5340 Audio DK cpuapp
         NCS base version: 2.3.0
         Cmake run : Thu Nov 07 15:59:22 2024
HL [00:00:00.006,439] <inf> fw_info: ------- DEBUG BUILD -------
HL [00:00:00.006,439] <inf> fw_info: HEADSET left device
HL [00:00:00.017,059] <inf> board_version: Compatible board/HW version found: 1.0.0
HL [00:00:02.051,605] <wrn> bt_hci_core: Controller to host flow control not supported
HL [00:00:02.054,565] <inf> bt_hci_core: No ID address. App must call settings_load()
HL [00:00:02.054,626] <inf> ble: MAC: 00:00:00:00:00:00 (public)
HL [00:00:02.055,206] <inf> ble: Controller version: 3424
HL [00:00:02.180,267] <inf> cis_headset: Set direct advertising to C5:24:9D:F9:E6:5B (random)
HL [00:00:02.180,908] <inf> cis_headset: Advertising successfully started
HL [00:00:03.027,343] <inf> cis_headset: Connected: C5:24:9D:F9:E6:5B (random)

Fullscreen SDK2.3.0_SuccessLog_GW.txt Download

GW [00:04:25.818,023] <wrn> bt_hci_core: opcode 0x206f status 0x0c
GW [00:04:25.818,237] <wrn> bt_hci_core: opcode 0x206f status 0x12
GW [00:04:25.818,237] <inf> cis_gateway: Stream 0x200046ec stopped
GW [00:04:25.819,000] <inf> cis_gateway: Disconnected: E7:F7:B5:23:BC:DE (random) (reason 0x08)
GW [00:04:25.819,091] <inf> cis_gateway: Stored bonding found: E7:F7:B5:23:BC:DE (random)
GW [00:04:25.819,122] <inf> cis_gateway: Scanning successfully started
GW [00:04:25.824,035] <wrn> streamctrl: Problem with sending LE audio data, ret: -140
GW [00:04:26.513,977] <inf> cis_gateway: Connected: E7:F7:B5:23:BC:DE (random)
GW [00:04:27.015,289] <inf> cis_gateway: Security changed: level 2
GW [00:04:28.715,362] <inf> cis_gateway: Stored bonding found: E7:F7:B5:23:BC:DE (random)
GW [00:04:28.715,942] <inf> cis_gateway: Scanning successfully started
GW [00:04:30.117,492] <inf> cis_gateway: Sink discover complete: err 0
GW [00:04:30.220,642] <inf> cis_gateway: LEFT sink stream configured
GW [00:04:30.223,327] <inf> cis_gateway: Stream QOS set: 0x200046ec
GW [00:04:30.227,783] <inf> cis_gateway: Stream enabled: 0x200046ec
GW [00:04:31.015,686] <inf> cis_gateway: Stream 0x200046ec started

Fullscreen SDK2.3.0_SuccessLog_HL.txt Download

*** Booting Zephyr OS build v3.2.99-ncs2 ***
I: Starting bootloader
I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Boot source: none
I: Swap type: none
I: Bootloader chainload address offset: 0xc000
*** Booting Zephyr OS build v3.2.99-ncs2 ***
HL [00:00:00.006,439] <inf> fw_info:
         nRF5340 Audio nRF5340 Audio DK cpuapp
         NCS base version: 2.3.0
         Cmake run : Thu Nov 07 15:59:22 2024
HL [00:00:00.006,439] <inf> fw_info: ------- DEBUG BUILD -------
HL [00:00:00.006,439] <inf> fw_info: HEADSET left device
HL [00:00:00.017,059] <inf> board_version: Compatible board/HW version found: 1.0.0
HL [00:00:02.052,062] <wrn> bt_hci_core: Controller to host flow control not supported
HL [00:00:02.054,992] <inf> bt_hci_core: No ID address. App must call settings_load()
HL [00:00:02.055,053] <inf> ble: MAC: 00:00:00:00:00:00 (public)
HL [00:00:02.055,633] <inf> ble: Controller version: 3424
HL [00:00:02.180,725] <inf> cis_headset: Set direct advertising to C5:24:9D:F9:E6:5B (random)
HL [00:00:02.181,365] <inf> cis_headset: Advertising successfully started
HL [00:00:03.551,727] <inf> cis_headset: Connected: C5:24:9D:F9:E6:5B (random)
HL [00:00:07.253,784] <inf> cis_headset: Codec config for LC3:
HL [00:00:07.253,814] <inf> cis_headset:        Frequency: 48000 Hz
HL [00:00:07.253,814] <inf> cis_headset:        Frame Duration: 10000 us
HL [00:00:07.253,814] <inf> cis_headset:        Channel allocation: 0x1
HL [00:00:07.253,845] <inf> cis_headset:        Octets per frame: 120 (96000 bps)
HL [00:00:07.253,845] <inf> cis_headset:        Frames per SDU: 1
HL [00:00:07.258,789] <inf> cis_headset: Presentation delay 10000 us is set by initiator
HL [00:00:07.953,796] <inf> cis_headset: Stream started
HL [00:00:08.064,605] <inf> audio_datapath: Drft comp state: CALIB
HL [00:00:08.065,612] <wrn> audio_datapath: Data received, total underruns: 790
HL [00:00:08.164,611] <inf> audio_datapath: Drft comp state: INIT
HL [00:00:08.165,618] <inf> audio_datapath: Drft comp state: CALIB
HL [00:00:08.166,595] <wrn> audio_datapath: Data received, total underruns: 791
HL [00:00:08.265,625] <inf> audio_datapath: Drft comp state: OFFSET
HL [00:00:08.726,104] <inf> audio_datapath: Drft comp state: LOCKED
HL [00:00:08.734,100] <inf> audio_datapath: Pres comp state: MEAS
HL [00:00:08.844,085] <inf> audio_datapath: Pres comp state: WAIT
HL [00:00:08.944,091] <inf> audio_datapath: Pres comp state: INIT
HL [00:00:08.954,101] <inf> audio_datapath: Pres comp state: MEAS
HL [00:00:09.065,093] <inf> audio_datapath: Pres comp state: LOCKED

[dejans]

Hi,

sometimes Link processing does not work correctly and the following log output:

. cis_gateway: Discovery failed: 14

Can you provide more information about this? How often is "sometimes"? When does this discovery error happen?

Can you try to update to the newest NCS version and test with it? Please also provide the same logs on both sides.

Best regards,
Dejan

[tommy]

Thank you for your reply.

 

When does this discovery error happen?
⇒As a procedure, turn on the power for both the headset and the gateway and link them.
After that, if you turn off and then turn on the power on the headset side only, the link sometimes fails to re-establish.

 

How often is "sometimes"?
⇒Occurs about once in 30 times.

 

Can you try to update to the newest NCS version and test with it? Please also provide the same logs on both sides.
⇒I have obtained the logs using SDK 2.8.0 and will send them to you. 
  Since there were no failures with SDK 2.8.0, only the logs from successful attempts are included.

Fullscreen SDK2.8.0_SuccessLog_GW.txt Download

GW [00:00:44.530,212] <wrn> bt_hci_core: opcode 0x206f status 0x0c
GW [00:00:44.530,578] <inf> bt_mgmt: Disconnected: FB:2A:C5:30:5D:F1 (random), reason 0x08
GW [00:00:44.530,609] <inf> main: Disconnection event. Num connections: 0
GW [00:00:44.532,714] <inf> bt_mgmt_scan: Local addr: 48:5E:E1:C2:11:93 (random). May time out. Updates not printed
GW [00:00:44.532,714] <inf> bt_mgmt_scan: Scanning successfully started
GW [00:00:44.532,714] <inf> unicast_client: Stream 0x20012294 stopped. Reason 8
GW [00:00:44.535,949] <inf> bt_mgmt_scan: Creating connection to bonded device: FB:2A:C5:30:5D:F1 (random)
GW [00:00:44.538,757] <wrn> unicast_client: No active streams
GW [00:00:44.538,757] <wrn> main: Sending operation cancelled
GW [00:00:44.542,205] <inf> bt_mgmt: Connected: FB:2A:C5:30:5D:F1 (random)
GW [00:00:44.542,236] <inf> main: Connection event. Num connections: 1
GW [00:00:44.612,243] <inf> main: Security changed
GW [00:00:44.822,479] <inf> bt_vol_ctlr: VCS discover finished
GW [00:00:45.172,515] <inf> main: Set members found: 1 of 2
GW [00:00:45.173,645] <inf> bt_mgmt_scan: Local addr: 48:5E:E1:C2:11:93 (random). May time out. Updates not printed
GW [00:00:45.173,645] <inf> bt_mgmt_scan: Scanning successfully started
GW [00:00:45.482,299] <inf> unicast_client: Discovered 1 sink endpoint(s) for device 0
GW [00:00:45.503,784] <inf> unicast_client: LEFT sink stream configured
GW [00:00:45.503,814] <inf> le_audio: LC3 codec config for sink:
GW [00:00:45.503,814] <inf> le_audio:   Frequency: 48000 Hz
GW [00:00:45.503,814] <inf> le_audio:   Duration: 10000 us
GW [00:00:45.503,814] <inf> le_audio:   Channel allocation: 0x1
GW [00:00:45.503,845] <inf> le_audio:   Octets per frame: 120 (96000 bps)
GW [00:00:45.503,845] <inf> le_audio:   Frames per SDU: 1
GW [00:00:46.032,318] <inf> unicast_client: Stream 0x20012294 started
GW [00:00:46.108,612] <inf> audio_datapath: Drft comp state: INIT
GW [00:00:46.109,588] <inf> audio_datapath: Drft comp state: CALIB
GW [00:00:46.209,533] <inf> audio_datapath: Drft comp state: INIT
GW [00:00:46.210,510] <inf> audio_datapath: Drft comp state: CALIB
GW [00:00:46.310,455] <inf> audio_datapath: Drft comp state: INIT
GW [00:00:46.311,462] <inf> audio_datapath: Drft comp state: CALIB
GW [00:00:46.411,376] <inf> audio_datapath: Drft comp state: OFFSET
GW [00:00:46.611,419] <inf> audio_datapath: Drft comp state: LOCKED

Fullscreen SDK2.8.0_SuccessLog_HL.txt Download

*** Booting nRF Connect SDK v2.8.0-a2386bfc8401 ***
*** Using Zephyr OS v3.7.99-0bc3393fb112 ***
HL [00:00:00.268,096] <inf> board_version: Compatible board/HW version found: 1.0.0
HL [00:00:00.300,506] <inf> fw_info:
         nRF5340 Audio nRF5340 Audio DK cpuapp
         NCS base version: 2.8.0
         Cmake run : Fri Nov 22 16:02:19 2024
HL [00:00:00.300,506] <inf> fw_info: ------- DEBUG BUILD -------
HL [00:00:00.300,506] <inf> fw_info: HEADSET left device
HL [00:00:00.372,711] <inf> bt_mgmt_ctlr_cfg: Controller: SoftDevice: Version 6.0 (0x0e), Revision 8270
HL [00:00:00.372,924] <inf> bt_mgmt: Local identity addr: FB:2A:C5:30:5D:F1 (random)
HL [00:00:00.401,458] <wrn> unicast_server: CSIP using the default SIRK, must be changed before production
HL [00:00:00.405,975] <inf> bt_mgmt_adv: Local addr: 43:BA:F1:32:7B:45 (random)
HL [00:00:00.406,066] <inf> bt_mgmt_adv: Adv directed to: E0:D7:9C:28:A7:C9 (random).
HL [00:00:00.406,646] <inf> bt_mgmt_adv: Advertising successfully started
HL [00:00:00.861,053] <inf> bt_mgmt: Connected: E0:D7:9C:28:A7:C9 (random)
HL [00:00:00.861,083] <inf> main: Connection event. Num connections: 1
HL [00:00:00.861,236] <inf> bt_mgmt_adv: RPA (Resolvable Private Address) expired.
HL [00:00:00.861,328] <inf> bt_mgmt_adv: Local addr: 43:BA:F1:32:7B:45 (random)
HL [00:00:00.932,037] <inf> main: Security changed
HL [00:00:00.932,250] <wrn> bt_gatt: Device is not subscribed to characteristic
HL [00:00:00.932,250] <wrn> bt_pacs: PACS notify failed: -22
HL [00:00:01.411,895] <inf> bt_content_ctrl_media: Discovery of MCS finished
HL [00:00:01.812,805] <inf> le_audio: LC3 codec config for sink:
HL [00:00:01.812,805] <inf> le_audio:   Frequency: 48000 Hz
HL [00:00:01.812,805] <inf> le_audio:   Duration: 10000 us
HL [00:00:01.812,805] <inf> le_audio:   Channel allocation: 0x1
HL [00:00:01.812,835] <inf> le_audio:   Octets per frame: 120 (96000 bps)
HL [00:00:01.812,835] <inf> le_audio:   Frames per SDU: 1
HL [00:00:01.832,672] <inf> main: Presentation delay 3000 us is set by initiator
HL [00:00:02.268,859] <inf> unicast_server: Stream 0x20010fdc started
HL [00:00:02.281,463] <wrn> audio_datapath: Data received, total under-runs: 1
HL [00:00:02.379,486] <inf> audio_datapath: Drft comp state: CALIB
HL [00:00:02.479,461] <inf> audio_datapath: Drft comp state: OFFSET
HL [00:00:02.879,638] <inf> audio_datapath: Drft comp state: LOCKED
HL [00:00:02.889,099] <inf> audio_datapath: Pres comp state: MEAS
HL [00:00:02.999,084] <inf> audio_datapath: Pres comp state: WAIT
HL [00:00:03.139,099] <inf> audio_datapath: Pres comp state: INIT
HL [00:00:03.149,108] <inf> audio_datapath: Pres comp state: MEAS
HL [00:00:03.259,094] <inf> audio_datapath: Pres comp state: LOCKED

[dejans]

Hi,

Thank you for additional logs. 

Since there are no errors when using NCS v2.8.0, I recommend that you continue using that NCS version if there isn't anything that is preventing you from doing that.

Best regards,
Dejan