Error log "Could not lookup stream by iso 0xXXXXXXXX" from unicast server if client release the stream #49733
Description
Describe the bug
If unicast client release a stream, the unicast server will see error log:
"bt_ascs: ascs_iso_disconnected: Could not lookup stream by iso 0x2000xxxx"
I'm using NCS which with Zephyr cherry-picked #49055 for unicast server, and use Android phone as unicast client for testing.
The Android phone will release the stream if there's no active audio stream sending. and at the moment when ISO channel disconnected, the error log will pop up.
To Reproduce
Steps to reproduce the behavior:
- Setup a unicast server and unicast client
- Setup an ISO stream between unicast client and server
- Unicast client releases the ISO stream
- The error "Could not lookup stream by iso 0xXXXXXXXX" shows up
Logs and console output
*** Booting Zephyr OS build zephyr-v3.1.0-3561-g5f71df773888 ***
HR [00:00:00.252,380] <inf> audio_sync_timer: Audio sync timer initialized
HR [00:00:00.252,990] <dbg> nrf5340_audio_dk_nrf5340_cpuapp: core_config: Setting gpiote latency to low power
HR [00:00:00.253,051] <dbg> nrf5340_audio_dk_nrf5340_cpuapp: remoteproc_mgr_boot: Network MCU released.
HR [00:00:00.259,429] <inf> fw_info:
nRF5340 Audio nRF5340 Audio DK cpuapp
NCS Version: 2.0.99
Cmake run : Tue Aug 30 18:42:02 2022
HR [00:00:00.259,429] <inf> fw_info: ------- DEBUG BUILD -------
HR [00:00:00.259,429] <inf> fw_info:
HEADSET right device
HR [00:00:00.270,050] <inf> board_version: Compatible board/HW version found: 1.0.0
HR [00:00:02.304,718] <wrn> ble: Failed to create ID
HR [00:00:02.307,708] <inf> fs_nvs: 6 Sectors of 4096 bytes
HR [00:00:02.307,739] <inf> fs_nvs: alloc wra: 0, ef0
HR [00:00:02.307,739] <inf> fs_nvs: data wra: 0, 178
HR [00:00:02.317,749] <wrn> bt_hci_core: Controller to host flow control not supported
HR [00:00:02.320,800] <inf> bt_hci_core: No ID address. App must call settings_load()
HR [00:00:02.320,861] <inf> ble: MAC: 00:00:00:00:00:00 (public)
HR [00:00:02.321,441] <inf> ble: Controller version: 3301
HR [00:00:02.446,777] <inf> cis_headset: Regular advertising started
*** Booting Zephyr OS build zephyr-v3.1.0-3561-g5f71df773888 ***
HR [00:00:00.252,471] <inf> audio_sync_timer: Audio sync timer initialized
HR [00:00:00.253,082] <dbg> nrf5340_audio_dk_nrf5340_cpuapp: core_config: Setting gpiote latency to low power
HR [00:00:00.253,143] <dbg> nrf5340_audio_dk_nrf5340_cpuapp: remoteproc_mgr_boot: Network MCU released.
HR [00:00:00.259,521] <inf> fw_info:
nRF5340 Audio nRF5340 Audio DK cpuapp
NCS Version: 2.0.99
Cmake run : Tue Aug 30 18:42:02 2022
HR [00:00:00.259,521] <inf> fw_info: ------- DEBUG BUILD -------
HR [00:00:00.259,521] <inf> fw_info:
HEADSET right device
HR [00:00:00.270,141] <inf> board_version: Compatible board/HW version found: 1.0.0
HR [00:00:02.304,809] <wrn> ble: Failed to create ID
HR [00:00:02.307,800] <inf> fs_nvs: 6 Sectors of 4096 bytes
HR [00:00:02.307,800] <inf> fs_nvs: alloc wra: 0, ee0
HR [00:00:02.307,800] <inf> fs_nvs: data wra: 0, 198
HR [00:00:02.317,810] <wrn> bt_hci_core: Controller to host flow control not supported
HR [00:00:02.320,861] <inf> bt_hci_core: No ID address. App must call settings_load()
HR [00:00:02.320,922] <inf> ble: MAC: 00:00:00:00:00:00 (public)
HR [00:00:02.321,502] <inf> ble: Controller version: 3301
HR [00:00:02.322,387] <inf> main: Clearing all bonds
HR [00:00:02.446,990] <inf> cis_headset: Regular advertising started
HR [00:00:12.550,476] <inf> cis_headset: Connected: 60:55:5D:E3:5A:8B (random)
HR [00:00:17.317,291] <dbg> bt_ascs: ascs_ase_cfg_changed: attr 0x83fe4 value 0x0001
HR [00:00:17.407,318] <dbg> bt_ascs: ascs_cp_cfg_changed: attr 0x84020 value 0x0001
HR [00:00:17.497,314] <dbg> bt_ascs: ascs_ase_read: conn 0x20002db8 attr 0x83fd0 buf 0x200173a6 len 64 offset 0
HR [00:00:17.497,344] <dbg> bt_ascs: ascs_ep_init: ep 0x2000ba34 id 0x01
HR [00:00:17.497,375] <dbg> bt_ascs: ascs_ep_get_status: ep 0x2000ba34 id 0x01 state idle
HR [00:00:35.633,483] <inf> cis_headset: Codec config for LC3:
--- 15 messages dropped ---
HR [00:00:35.633,483] <inf> cis_headset: Frequency: 48000 Hz
HR [00:00:35.633,514] <inf> cis_headset: Frame Duration: 10000 us
HR [00:00:35.633,514] <inf> cis_headset: Channel allocation: 0x2
HR [00:00:35.633,514] <inf> cis_headset: Octets per frame: 120 (96000 kbps)
HR [00:00:35.633,514] <inf> cis_headset: Frames per SDU: 1
HR [00:00:35.633,544] <dbg> bt_ascs: ase_stream_add: ase 0x2000ba30 stream 0x2000a728
HR [00:00:35.633,544] <dbg> bt_ascs: ascs_cp_rsp_add: id 0x01 op Config Codec (0x01) code Success (0x00) reason None (0x00)
HR [00:00:35.633,575] <dbg> bt_ascs: ascs_ep_set_state: ep 0x2000ba34 id 0x01 idle -> codec-configured
HR [00:00:35.633,575] <dbg> bt_ascs: ase_status_changed: ase 0x2000ba30 conn 0x20002db8
HR [00:00:35.633,605] <dbg> bt_ascs: ascs_cp_notify: ascs 0x2000ba24 handle 0x0013 len 5
HR [00:00:35.633,728] <dbg> bt_ascs: ase_process: ase 0x2000ba30, ep 0x2000ba34, ep.stream 0x2000a728
--- 5 messages dropped ---
HR [00:00:35.633,819] <dbg> bt_ascs: ascs_codec_data_add: data
01 |.
HR [00:00:35.633,819] <dbg> bt_ascs: ascs_codec_data_add: #2: data type 0x03 len 4
HR [00:00:35.633,850] <dbg> bt_ascs: ascs_codec_data_add: data
02 00 00 00 |....
HR [00:00:35.633,850] <dbg> bt_ascs: ascs_codec_data_add: #3: data type 0x04 len 2
HR [00:00:35.633,850] <dbg> bt_ascs: ascs_codec_data_add: data
78 00 |x.
HR [00:00:35.633,880] <dbg> bt_ascs: ascs_codec_data_add: #4: data type 0x05 len 1
HR [00:00:35.633,880] <dbg> bt_ascs: ascs_codec_data_add: data
01 |.
--- 13 messages dropped ---
HR [00:00:35.813,354] <dbg> bt_ascs: ascs_cp_write: conn 0x20002db8 attr 0x8400c buf 0x20015dd0 len 11 op Enable (0x03)
--- 1 messages dropped ---
HR [00:00:35.813,354] <dbg> bt_ascs: ascs_enable: num_ases 1
HR [00:00:35.813,354] <dbg> bt_ascs: ascs_enable: ase 0x01 meta->len 7
HR [00:00:35.813,354] <dbg> bt_ascs: ase_enable: ase 0x2000ba30 buf->len 7
HR [00:00:35.813,385] <dbg> bt_ascs: ascs_ep_set_metadata: ep 0x2000ba34 len 7 codec 0x2000ba44
HR [00:00:35.813,385] <dbg> bt_ascs: ascs_parse_metadata: #1 type 0x02 len 2
HR [00:00:35.813,385] <dbg> bt_ascs: ascs_parse_metadata: #2 type 0x05 len 1
HR [00:00:35.813,415] <dbg> bt_ascs: ascs_codec_store_metadata: #0: data: 0400
HR [00:00:35.813,446] <dbg> bt_ascs: ascs_codec_store_metadata: #1: data: 02
HR [00:00:35.813,446] <dbg> bt_ascs: ascs_ep_set_state: ep 0x2000ba34 id 0x01 qos-configured -> enabling
HR [00:00:35.813,476] <dbg> bt_ascs: ase_status_changed: ase 0x2000ba30 conn 0x20002db8
HR [00:00:35.813,507] <dbg> bt_ascs: ascs_cp_rsp_add: id 0x01 op Enable (0x03) code Success (0x00) reason None (0x00)
HR [00:00:35.813,507] <dbg> bt_ascs: ascs_cp_notify: ascs 0x2000ba24 handle 0x0013 len 5
HR [00:00:35.813,629] <dbg> bt_ascs: ase_process: ase 0x2000ba30, ep 0x2000ba34, ep.stream 0x2000a728
HR [00:00:35.813,659] <dbg> bt_ascs: ascs_ep_get_status: ep 0x2000ba34 id 0x01 state enabling
HR [00:00:35.813,659] <dbg> bt_ascs: ascs_codec_data_add: #0: meta type 0x02 len 2
HR [00:00:35.813,659] <dbg> bt_ascs: ascs_codec_data_add: meta
04 00 |..
HR [00:00:35.813,690] <dbg> bt_ascs: ascs_codec_data_add: #1: meta type 0x05 len 1
HR [00:00:35.813,690] <dbg> bt_ascs: ascs_codec_data_add: meta
02 |.
HR [00:00:35.813,720] <dbg> bt_ascs: ascs_ep_get_status_enable: dir 0x01 cig 0x01 cis 0x00
HR [00:00:35.828,399] <wrn> audio_datapath: I2S RX overrun. Single msg
HR [00:00:36.544,250] <dbg> bt_ascs: ascs_iso_connected: stream 0x2000a728 ep 0x2000ba34 dir 1
HR [00:00:36.544,250] <dbg> bt_ascs: ascs_ep_set_state: ep 0x2000ba34 id 0x01 enabling -> streaming
HR [00:00:36.544,250] <dbg> bt_ascs: ase_status_changed: ase 0x2000ba30 conn 0x20002db8
HR [00:00:36.544,311] <dbg> bt_ascs: ase_process: ase 0x2000ba30, ep 0x2000ba34, ep.stream 0x2000a728
HR [00:00:36.544,311] <dbg> bt_ascs: ascs_ep_get_status: ep 0x2000ba34 id 0x01 state streaming
HR [00:00:36.544,342] <dbg> bt_ascs: ascs_codec_data_add: #0: meta type 0x02 len 2
HR [00:00:36.544,342] <dbg> bt_ascs: ascs_codec_data_add: meta
04 00 |..
HR [00:00:36.544,342] <dbg> bt_ascs: ascs_codec_data_add: #1: meta type 0x05 len 1
HR [00:00:36.544,372] <dbg> bt_ascs: ascs_codec_data_add: meta
02 |.
HR [00:00:36.544,372] <dbg> bt_ascs: ascs_ep_get_status_enable: dir 0x01 cig 0x01 cis 0x00
HR [00:00:36.613,433] <inf> audio_datapath: Drft comp state: CALIB
HR [00:00:36.614,410] <wrn> audio_datapath: Data received, total underruns: 793
HR [00:00:36.713,439] <inf> audio_datapath: Drft comp state: OFFSET
HR [00:00:36.885,192] <wrn> audio_datapath: Data received, total underruns: 794
HR [00:00:37.138,031] <inf> audio_datapath: Drft comp state: LOCKED
HR [00:00:37.142,669] <inf> audio_datapath: Pres comp state: MEAS
HR [00:00:37.252,685] <inf> audio_datapath: Pres comp state: LOCKED
HR [00:00:44.483,032] <inf> audio_datapath: sdu_ref_us not from consecutive frames
HR [00:00:44.483,032] <inf> audio_datapath: Pres comp state: WAIT
HR [00:00:44.485,351] <wrn> audio_datapath: Data received, total underruns: 804
HR [00:00:44.573,028] <inf> audio_datapath: Pres comp state: INIT
HR [00:00:44.583,038] <inf> audio_datapath: Pres comp state: MEAS
HR [00:00:44.693,054] <inf> audio_datapath: Pres comp state: LOCKED
HR [00:01:02.363,891] <inf> audio_datapath: sdu_ref_us not from consecutive frames
HR [00:01:02.363,922] <inf> audio_datapath: Pres comp state: WAIT
HR [00:01:02.366,210] <wrn> audio_datapath: Data received, total underruns: 814
HR [00:01:02.453,918] <inf> audio_datapath: Pres comp state: INIT
HR [00:01:02.463,897] <inf> audio_datapath: Pres comp state: MEAS
HR [00:01:02.573,913] <inf> audio_datapath: Pres comp state: LOCKED
HR [00:01:45.819,030] <wrn> audio_datapath: Data received, total underruns: 815
HR [00:02:28.338,684] <inf> audio_datapath: sdu_ref_us not from consecutive frames
HR [00:02:28.338,684] <inf> audio_datapath: Pres comp state: WAIT
HR [00:02:28.339,721] <wrn> audio_datapath: Data received, total underruns: 4074
HR [00:02:29.274,810] <wrn> audio_datapath: In I2S TX underrun condition, total: 5000
HR [00:02:30.073,547] <dbg> bt_ascs: ascs_cp_write: conn 0x20002db8 attr 0x8400c buf 0x20015dd0 len 3 op Release (0x08)
HR [00:02:30.073,547] <dbg> bt_ascs: ascs_release: num_ases 1
HR [00:02:30.073,577] <dbg> bt_ascs: ascs_release: ase 0x01
HR [00:02:30.073,577] <dbg> bt_ascs: ase_release: ase 0x2000ba30
HR [00:02:30.073,577] <dbg> bt_ascs: ascs_ep_set_state: ep 0x2000ba34 id 0x01 streaming -> releasing
HR [00:02:30.073,608] <dbg> bt_ascs: ase_status_changed: ase 0x2000ba30 conn 0x20002db8
HR [00:02:30.073,608] <dbg> bt_ascs: ascs_cp_rsp_add: id 0x01 op Release (0x08) code Success (0x00) reason None (0x00)
HR [00:02:30.073,638] <dbg> bt_ascs: ascs_cp_notify: ascs 0x2000ba24 handle 0x0013 len 5
HR [00:02:30.073,760] <dbg> bt_ascs: ase_process: ase 0x2000ba30, ep 0x2000ba34, ep.stream 0x2000a728
HR [00:02:30.073,760] <dbg> bt_ascs: ascs_ep_get_status: ep 0x2000ba34 id 0x01 state releasing
HR [00:02:30.073,822] <dbg> bt_ascs: ascs_ep_set_state: ep 0x2000ba34 id 0x01 releasing -> idle
HR [00:02:30.073,883] <dbg> bt_ascs: ase_status_changed: ase 0x2000ba30 conn 0x20002db8
HR [00:02:30.073,944] <dbg> bt_ascs: ase_process: ase 0x2000ba30, ep 0x2000ba34, ep.stream (nil)
HR [00:02:30.073,974] <dbg> bt_ascs: ascs_ep_get_status: ep 0x2000ba34 id 0x01 state idle
HR [00:02:30.348,907] <err> bt_ascs: ascs_iso_disconnected: Could not lookup stream by iso 0x2000bb20
HR [00:02:34.275,054] <wrn> audio_datapath: In I2S TX underrun condition, total: 10000
HR [00:02:39.275,299] <wrn> audio_datapath: In I2S TX underrun condition, total: 15000
HR [00:02:44.275,512] <wrn> audio_datapath: In I2S TX underrun condition, total: 20000
HR [00:02:49.275,756] <wrn> audio_datapath: In I2S TX underrun condition, total: 25000
Metadata
Metadata
Assignees
Labels
Type
Projects
Status