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.
We have gotton the logs by EVK.
Is there anything you think might be the cause?
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
>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.
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
*** 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)
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
*** 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
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
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.
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
*** 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
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
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