Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Bluetooth: LE: Audio: kernel panic with Bap Unicast Server sample when music stream is started (board nRF-5340-Audio-DK) #83798

Open
dev-pac opened this issue Jan 10, 2025 · 20 comments
Assignees
Labels
area: Bluetooth Controller area: Bluetooth ISO Bluetooth LE Isochronous Channels area: Bluetooth bug The issue is a bug, or the PR is fixing a bug priority: low Low impact/importance bug

Comments

@dev-pac
Copy link

dev-pac commented Jan 10, 2025

Describe the bug

When my phone ( samsung zflip 4 ) start the music with the "bap unicast server" a kernel panic is trigger after 1/2 sec

To Reproduce

Steps to reproduce the behavior:

  1. edit samples/bluetooth/bap_unicast_server/prj.conf and add:
#### Custom cfg ####
CONFIG_LOG=y
# CONFIG_BT_LOG_LEVEL_DBG=y
CONFIG_CONSOLE=y
CONFIG_RTT_CONSOLE=y
CONFIG_LOG_PRINTK=y
CONFIG_USE_SEGGER_RTT=y
CONFIG_LOG_BUFFER_SIZE=4096

# samsung zflip 4 send metadata supperior to default value (4)
## <wrn> bt_ascs: Not enough space for Codec Config Metadata: 7 > 4
## <err> bt_ascs: Enable rejected: err -12, code 13, reason 0
CONFIG_BT_AUDIO_CODEC_CFG_MAX_METADATA_SIZE=15
CONFIG_BT_AUDIO_CODEC_CAP_MAX_METADATA_SIZE=15
  1. west build -b nrf5340_audio_dk/nrf5340/cpuapp --sysbuild samples/bluetooth/bap_unicast_server/
  2. west flash
  3. use a phone with BLE audio support then bound + stream a music

Expected behavior

No kernel panic and stream proceeded

Impact

Logs and console output

Logs:

SEGGER J-Link V7.94b - Real time terminal output
SEGGER J-Link (unknown) V1.0, SN=1050177497
Process: JLinkGDBServerCLExe
*** Booting Zephyr OS build v3.7.0 ***
[00:00:00.382,904] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
[00:00:00.382,934] <inf> bt_hci_core: HW Variant: nRF53x (0x0003)
[00:00:00.382,965] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 3.7 Build 0
[00:00:00.384,765] <inf> bt_hci_core: Identity: E8:19:DF:C5:36:52 (random)
[00:00:00.384,796] <inf> bt_hci_core: HCI: version 5.4 (0x0d) revision 0x0000, manufacturer 0x05f1
[00:00:00.384,826] <inf> bt_hci_core: LMP: version 5.4 (0x0d) subver 0xffff
Bluetooth initialized
Location successfully set
Supported contexts successfully set
Available contexts successfully set
Advertising successfully started
Connected: 7E:E0:A3:C8:1F:4F (random)
ASE Codec Config: conn 0x200022e8 ep 0x200029ac dir 1
codec_cfg 0x06 cid 0x0000 vid 0x0000 count 19
data: type 0x01 value_len 1
08
data: type 0x02 value_len 1
01
data: type 0x03 value_len 4
00000000
data: type 0x04 value_len 2
7800
data: type 0x05 value_len 1
01
  Frequency: 48000 Hz
  Frame Duration: 10000 us
  Channel allocation: 0x0
  Octets per frame: 120 (negative means value not pressent)
  Frames per SDU: 1
ASE Codec Config stream 0x20005498
QoS: stream 0x20005498 qos 0x20007988
QoS: interval 10000 framing 0x00 phy 0x02 sdu 120 rtn 2 latency 10 pd 40000
Enable: stream 0x20005498 meta_len 7
RX stream 0x20005498 len 0
RX stream 0x20005498 len 0
RX stream 0x20005498 len 0
RX stream 0x20005498 len 0
Release: stream 0x20005498
Audio Stream 0x20005498 stopped with reason 0x13
ASSERTION FAIL [err == 0] @ WEST_TOPDIR/zephyr/subsys/bluetooth/host/hci_core.c:410
        Controller unresponsive, command opcode 0x0406 timeout with err -11
[00:01:17.525,970] <err> os: r0/a1:  0x00000003  r1/a2:  0x00000000  r2/a3:  0x00000002
[00:01:17.526,000] <err> os: r3/a4:  0x00000003 r12/ip:  0x00000010 r14/lr:  0x00005d9f
[00:01:17.526,000] <err> os:  xpsr:  0x01000000
[00:01:17.526,000] <err> os: s[ 0]:  0x200098d0  s[ 1]:  0x00000003  s[ 2]:  0x20009880  s[ 3]:  0x20009880
[00:01:17.526,031] <err> os: s[ 4]:  0x00000000  s[ 5]:  0x00000001  s[ 6]:  0x20009890  s[ 7]:  0x20009890
[00:01:17.526,031] <err> os: s[ 8]:  0x00000006  s[ 9]:  0x20002608  s[10]:  0x20005498  s[11]:  0x20005cb0
[00:01:17.526,062] <err> os: s[12]:  0x200098d0  s[13]:  0xffffffff  s[14]:  0xffffffff  s[15]:  0x00000000
[00:01:17.526,062] <err> os: fpscr:  0x00000000
[00:01:17.526,062] <err> os: Faulting instruction address (r15/pc): 0x00005dae
[00:01:17.526,092] <err> os: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0
[00:01:17.526,123] <err> os: Current thread: 0x20002f28 (unknown)
[00:01:18.045,745] <err> os: Halting system

advertising debug logs
bounding debug logs
stream started debug logs

Environment (please complete the following information):

  • Zephyr 3.7 (LTS)
  • board nRF-5340-Audio-DK

Additional context

@dev-pac dev-pac added the bug The issue is a bug, or the PR is fixing a bug label Jan 10, 2025
Copy link

Hi @dev-pac! We appreciate you submitting your first issue for our open-source project. 🌟

Even though I'm a bot, I can assure you that the whole community is genuinely grateful for your time and effort. 🤖💙

@hermabe
Copy link
Member

hermabe commented Jan 10, 2025

As the assertion message says, the controller is not responding to the disconnect command. Can you enable logging on the netcore and see what happens there? Most likely there is an assert or fault there that prevents it from responding.

@dev-pac
Copy link
Author

dev-pac commented Jan 10, 2025

As the assertion message says, the controller is not responding to the disconnect command. Can you enable logging on the netcore and see what happens there? Most likely there is an assert or fault there that prevents it from responding.

How can i get logs from cpunet ?

tried with RTT added in hci_ipc prj.conf but nothing received:

#### Custom cfg ####
CONFIG_LOG=y
CONFIG_CONSOLE=y
CONFIG_RTT_CONSOLE=y
CONFIG_LOG_PRINTK=y
CONFIG_USE_SEGGER_RTT=y
CONFIG_LOG_BUFFER_SIZE=4096

@cvinayak
Copy link
Contributor

@dev-pac The conf file for hci_ipc for ISO features is nrf5340_cpunet_iso-bt_ll_sw_split.conf, by default boot banner and assertions should be output... do you see the boot banner?

@cvinayak
Copy link
Contributor

@dev-pac are you building for nrf5340dk and flashing to nrf5340_audio_dk?

west build -b nrf5340dk/nrf5340/cpuapp --sysbuild samples/bluetooth/bap_unicast_server/

@dev-pac
Copy link
Author

dev-pac commented Jan 10, 2025

@dev-pac are you building for nrf5340dk and flashing to nrf5340_audio_dk?

west build -b nrf5340dk/nrf5340/cpuapp --sysbuild samples/bluetooth/bap_unicast_server/

I don't understand your question , west build is -b nrf5340dk/nrf5340/cpuappso it's for nrf5340dk and yes board is nrf5340_audio_dk ( specify in title issue and environment description )

@cvinayak
Copy link
Contributor

cvinayak commented Jan 10, 2025

Do you have problem building for audio dk and flashing on audio dk? (steps to reproduce mentioned by you, is that in sync?)

west build -b nrf5340_audio_dk/nrf5340/cpuapp --sysbuild samples/bluetooth/bap_unicast_server/

@dev-pac
Copy link
Author

dev-pac commented Jan 10, 2025

Do you have problem building for audio dk and flashing on audio dk?

west build -b nrf5340_audio_dk/nrf5340/cpuapp --sysbuild samples/bluetooth/bap_unicast_server/

No problem with the build or with the flash of the sample.

@cvinayak
Copy link
Contributor

Please update the steps to reproduce in the description, as it is misleading.

@dev-pac
Copy link
Author

dev-pac commented Jan 10, 2025

Please update the steps to reproduce in the description, as it is misleading.

I don't understand, which steps are missing for you? It's just the build and flash example of zephyr on the nrf5340_audio_dk board ?

@dev-pac
Copy link
Author

dev-pac commented Jan 10, 2025

my bad, I just noticed that it was nrf5340_audio_dk in your comment and nrf5340dk in my build command.

steps updated

@dev-pac
Copy link
Author

dev-pac commented Jan 10, 2025

Logs with correct board :

*** Booting Zephyr OS build v3.7.0 ***
[00:00:00.284,362] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
[00:00:00.284,393] <inf> bt_hci_core: HW Variant: nRF53x (0x0003)
[00:00:00.284,423] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 3.7 Build 0
[00:00:00.286,193] <inf> bt_hci_core: Identity: E8:19:DF:C5:36:52 (random)
[00:00:00.286,224] <inf> bt_hci_core: HCI: version 5.4 (0x0d) revision 0x0000, manufacturer 0x05f1
[00:00:00.286,254] <inf> bt_hci_core: LMP: version 5.4 (0x0d) subver 0xffff
Bluetooth initialized
Location successfully set
Supported contexts successfully set
Available contexts successfully set
Advertising successfully started
Connected: 40:CD:7E:7B:5A:EB (random)
ASE Codec Config: conn 0x200022e8 ep 0x200029ac dir 1
codec_cfg 0x06 cid 0x0000 vid 0x0000 count 19
data: type 0x01 value_len 1
08
data: type 0x02 value_len 1
01
data: type 0x03 value_len 4
00000000
data: type 0x04 value_len 2
7800
data: type 0x05 value_len 1
01
  Frequency: 48000 Hz
  Frame Duration: 10000 us
  Channel allocation: 0x0
  Octets per frame: 120 (negative means value not pressent)
  Frames per SDU: 1
ASE Codec Config stream 0x20005498
QoS: stream 0x20005498 qos 0x20007988
QoS: interval 10000 framing 0x00 phy 0x02 sdu 120 rtn 2 latency 10 pd 40000
Enable: stream 0x20005498 meta_len 7
RX stream 0x20005498 len 0
RX stream 0x20005498 len 0
Release: stream 0x20005498
Audio Stream 0x20005498 stopped with reason 0x13
ASSERTION FAIL [err == 0] @ WEST_TOPDIR/zephyr/subsys/bluetooth/host/hci_core.c:410
        Controller unresponsive, command opcode 0x0406 timeout with err -11
[00:00:37.642,791] <err> os: r0/a1:  0x00000003  r1/a2:  0x00000000  r2/a3:  0x00000002
[00:00:37.642,822] <err> os: r3/a4:  0x00000003 r12/ip:  0x00000010 r14/lr:  0x00005db3
[00:00:37.642,822] <err> os:  xpsr:  0x01000000
[00:00:37.642,822] <err> os: s[ 0]:  0x20008cd0  s[ 1]:  0x00000003  s[ 2]:  0x20008c80  s[ 3]:  0x20008c80
[00:00:37.642,852] <err> os: s[ 4]:  0x00000000  s[ 5]:  0x00000001  s[ 6]:  0x20008c90  s[ 7]:  0x20008c90
[00:00:37.642,852] <err> os: s[ 8]:  0x00000006  s[ 9]:  0x20002608  s[10]:  0x20005498  s[11]:  0x20005cb0
[00:00:37.642,883] <err> os: s[12]:  0x20008cd0  s[13]:  0xffffffff  s[14]:  0xffffffff  s[15]:  0x00000000
[00:00:37.642,883] <err> os: fpscr:  0x00000000
[00:00:37.642,883] <err> os: Faulting instruction address (r15/pc): 0x00005dc2
[00:00:37.642,913] <err> os: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0
[00:00:37.642,944] <err> os: Current thread: 0x20002f28 (unknown)
[00:00:38.161,285] <err> os: Halting system

@cvinayak
Copy link
Contributor

@dev-pac The conf file for hci_ipc for ISO features is nrf5340_cpunet_iso-bt_ll_sw_split.conf, by default boot banner and assertions should be output... do you see the boot banner?

did you check this?

@dev-pac
Copy link
Author

dev-pac commented Jan 10, 2025

For hci_ipc build i have :
Merged configuration '/workspaces/bolt-simple-app/zephyr/samples/bluetooth/hci_ipc/nrf5340_cpunet_iso-bt_ll_sw_split.conf'

What i should add to get logs of cpunet, i'm using the nrfconnect vscode extension.
With the extension RTT from cpuapp are displayed but nothing on cpunet RTT

@cvinayak
Copy link
Contributor

By default it has CONFIG_UART_CONSOLE=y, CONFIG_BOOT_BANNER=y, CONFIG_BT_ASSERT=y and CONFIG_BT_ASSERT_VERBOSE=y, that should give the boot banner and assertion failure output in the UART. Use your favorite terminal application (i am not using VSCode now, you can use one in VSCode?).

@dev-pac
Copy link
Author

dev-pac commented Jan 10, 2025

logs from ttyACM0 :

---- Opened the serial port /dev/ttyACM0 ----
*** Booting Zephyr OS build v3.7.0 ***
[00:00:00.285,278] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
[00:00:00.285,308] <inf> bt_hci_core: HW Variant: nRF53x (0x0003)
[00:00:00.285,339] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 3.7 Build 0
[00:00:00.287,780] <inf> bt_hci_core: Identity: E8:19:DF:C5:36:52 (random)
[00:00:00.287,811] <inf> bt_hci_core: HCI: version 5.4 (0x0d) revision 0x0000, manufacturer 0x05f1
[00:00:00.287,841] <inf> bt_hci_core: LMP: version 5.4 (0x0d) subver 0xffff
Bluetooth initialized
Location successfully set
Supported contexts successfully set
Available contexts successfully set
Advertising successfully started
Connected: 4C:70:A8:DF:65:C1 (random)
[00:01:01.076,721] <wrn> bt_conn: conn 0x200022e8 failed to establish. RF noise?
Disconnected: 4C:70:A8:DF:65:C1 (random) (reason 0x3e)
Advertising successfully started
Connected: 4C:70:A8:DF:65:C1 (random)
ASE Codec Config: conn 0x200022e8 ep 0x200029ac dir 1
codec_cfg 0x06 cid 0x0000 vid 0x0000 count 19
data: type 0x01 value_len 1
08
data: type 0x02 value_len 1
01
data: type 0x03 value_len 4
00000000
data: type 0x04 value_len 2
7800
data: type 0x05 value_len 1
01
  Frequency: 48000 Hz
  Frame Duration: 10000 us
  Channel allocation: 0x0
  Octets per frame: 120 (negative means value not pressent)
  Frames per SDU: 1
ASE Codec Config stream 0x20005498
QoS: stream 0x20005498 qos 0x20007988
QoS: interval 10000 framing 0x00 phy 0x02 sdu 120 rtn 2 latency 10 pd 40000
Enable: stream 0x20005498 meta_len 7

logs from ttyACMC1

---- Opened the serial port /dev/ttyACM1 ----
*** Booting Zephyr OS build v3.7.0 ***
[00:00:00.005,737] <inf> bt_hci_raw: Bluetooth enabled in RAW mode
[00:00:00.006,378] <inf> hci_ipc: Received message of 4 bytes.
--- 31 messages dropped ---
[00:00:00.019,714] <inf> hci_ipc: Received message of 4 bytes.
[00:00:00.019,927] <inf> hci_ipc: Sent message of 15 bytes.
[00:00:00.020,141] <inf> hci_ipc: Received message of 8 bytes.
[00:00:00.020,355] <inf> hci_ipc: Sent message of 7 bytes.
[00:00:00.020,568] <inf> hci_ipc: Received message of 4 bytes.
[00:00:00.020,782] <inf> hci_ipc: Sent message of 8 bytes.
[00:00:00.020,996] <inf> hci_ipc: Received message of 12 bytes.
[00:00:00.021,209] <inf> hci_ipc: Sent message of 7 bytes.
[00:00:00.021,423] <inf> hci_ipc: Received message of 12 bytes.
[00:00:00.021,636] <inf> hci_ipc: Sent message of 7 bytes.
[00:00:00.021,850] <inf> hci_ipc: Received message of 4 bytes.
[00:00:00.022,064] <inf> hci_ipc: Sent message of 19 bytes.
[00:00:00.022,369] <inf> hci_ipc: Received message of 4 bytes.
[00:00:00.022,613] <inf> hci_ipc: Sent message of 71 bytes.
[00:00:00.022,827] <inf> hci_ipc: Received message of 4 bytes.
[00:00:00.023,040] <inf> hci_ipc: Sent message of 15 bytes.
[00:00:00.023,254] <inf> hci_ipc: Received message of 4 bytes.
[00:00:00.023,468] <inf> hci_ipc: Sent message of 13 bytes.
[00:00:00.023,681] <inf> hci_ipc: Received message of 4 bytes.
[00:00:00.023,895] <inf> hci_ipc: Sent message of 30 bytes.
[00:00:00.024,139] <inf> hci_ipc: Received message of 10 bytes.
[00:00:00.024,353] <inf> hci_ipc: Sent message of 7 bytes.
[00:00:00.025,024] <inf> hci_ipc: Received message of 29 bytes.
[00:00:00.025,329] <inf> hci_ipc: Sent message of 8 bytes.
[00:00:00.025,543] <inf> hci_ipc: Received message of 11 bytes.
[00:00:00.025,787] <inf> hci_ipc: Sent message of 7 bytes.
[00:00:00.026,031] <inf> hci_ipc: Received message of 47 bytes.
[00:00:00.026,275] <inf> hci_ipc: Sent message of 7 bytes.
[00:00:00.026,550] <inf> hci_ipc: Received message of 10 bytes.
[00:00:00.027,008] <inf> hci_ipc: Sent message of 7 bytes.
[00:00:00.536,529] <inf> sync_rtc: Updated timestamp to synchronized RTC by 8621 ticks (263092us)
[00:01:00.905,731] <inf> hci_ipc: Sent message of 34 bytes.
[00:01:00.905,853] <inf> hci_ipc: Sent message of 9 bytes.
[00:01:00.906,219] <inf> hci_ipc: Received message of 6 bytes.
[00:01:00.906,463] <inf> hci_ipc: Sent message of 7 bytes.
[00:01:00.906,646] <inf> hci_ipc: Received message of 11 bytes.
[00:01:00.906,890] <inf> hci_ipc: Sent message of 7 bytes.
[00:01:00.907,073] <inf> hci_ipc: Received message of 4 bytes.
[00:01:00.907,287] <inf> hci_ipc: Sent message of 15 bytes.
[00:01:00.907,501] <inf> hci_ipc: Received message of 10 bytes.
[00:01:00.907,714] <inf> hci_ipc: Sent message of 9 bytes.
[00:01:01.076,660] <inf> hci_ipc: Sent message of 7 bytes.
[00:01:01.077,270] <inf> hci_ipc: Received message of 10 bytes.
[00:01:01.077,697] <inf> hci_ipc: Sent message of 7 bytes.
[00:01:01.633,331] <inf> hci_ipc: Sent message of 34 bytes.
[00:01:01.633,422] <inf> hci_ipc: Sent message of 9 bytes.
[00:01:01.633,789] <inf> hci_ipc: Received message of 6 bytes.
[00:01:01.634,033] <inf> hci_ipc: Sent message of 7 bytes.
[00:01:01.634,216] <inf> hci_ipc: Received message of 11 bytes.
[00:01:01.634,460] <inf> hci_ipc: Sent message of 7 bytes.
[00:01:01.634,643] <inf> hci_ipc: Received message of 4 bytes.
[00:01:01.634,857] <inf> hci_ipc: Sent message of 15 bytes.
[00:01:01.635,070] <inf> hci_ipc: Received message of 10 bytes.
[00:01:01.635,284] <inf> hci_ipc: Sent message of 9 bytes.
[00:01:01.674,987] <inf> hci_ipc: Sent message of 15 bytes.
[00:01:01.735,412] <inf> hci_ipc: Sent message of 9 bytes.
[00:01:01.765,075] <inf> hci_ipc: Sent message of 14 bytes.
[00:01:01.824,981] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:01.825,469] <inf> hci_ipc: Received message of 9 bytes.
[00:01:01.825,653] <inf> hci_ipc: Received message of 14 bytes.
[00:01:01.825,714] <inf> bt_ctlr_ull_conn: incoming Tx: count= 0, len= 0, rate= 0 bps.
[00:01:01.825,866] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:01.827,606] <inf> hci_ipc: Received message of 9 bytes.
[00:01:01.827,789] <inf> hci_ipc: Received message of 16 bytes.
[00:01:01.855,224] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:01.885,070] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:01.885,131] <inf> hci_ipc: Sent message of 32 bytes.
[00:01:01.885,528] <inf> hci_ipc: Sent message of 32 bytes.
[00:01:01.885,955] <inf> hci_ipc: Received message of 9 bytes.
[00:01:01.886,169] <inf> hci_ipc: Sent message of 20 bytes.
[00:01:01.886,383] <inf> hci_ipc: Received message of 9 bytes.
[00:01:01.887,603] <inf> hci_ipc: Received message of 9 bytes.
[00:01:01.887,817] <inf> hci_ipc: Received message of 74 bytes.
[00:01:01.887,969] <inf> hci_ipc: Received message of 26 bytes.
[00:01:01.915,466] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:01.945,098] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:01.945,190] <inf> hci_ipc: Sent message of 26 bytes.
[00:01:01.945,404] <inf> hci_ipc: Received message of 9 bytes.
[00:01:01.945,617] <inf> hci_ipc: Received message of 26 bytes.
[00:01:02.004,791] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:03.385,131] <inf> hci_ipc: Sent message of 26 bytes.
[00:01:03.389,617] <inf> hci_ipc: Received message of 9 bytes.
[00:01:03.389,801] <inf> hci_ipc: Received message of 26 bytes.
[00:01:03.389,892] <inf> bt_ctlr_ull_conn: incoming Tx: count= 5, len= 131, rate= 8735 bps.
[00:01:03.445,220] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:03.445,312] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:03.445,526] <inf> hci_ipc: Received message of 22 bytes.
[00:01:03.445,770] <inf> hci_ipc: Sent message of 9 bytes.
[00:01:03.505,065] <inf> hci_ipc: Sent message of 7 bytes.
[00:01:03.565,124] <inf> hci_ipc: Sent message of 26 bytes.
[00:01:03.565,551] <inf> hci_ipc: Received message of 9 bytes.
[00:01:03.566,040] <inf> hci_ipc: Sent message of 17 bytes.
[00:01:03.566,131] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:03.566,284] <inf> hci_ipc: Received message of 43 bytes.
[00:01:03.566,528] <inf> hci_ipc: Sent message of 7 bytes.
[00:01:03.566,711] <inf> hci_ipc: Received message of 12 bytes.
[00:01:03.566,925] <inf> hci_ipc: Sent message of 7 bytes.
[00:01:03.567,108] <inf> hci_ipc: Received message of 5 bytes.
[00:01:03.567,321] <inf> hci_ipc: Sent message of 7 bytes.
[00:01:03.567,504] <inf> hci_ipc: Received message of 9 bytes.
[00:01:03.567,779] <inf> hci_ipc: Received message of 9 bytes.
[00:01:03.567,993] <inf> hci_ipc: Received message of 14 bytes.
[00:01:03.624,877] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.075,164] <inf> hci_ipc: Sent message of 18 bytes.
[00:01:04.075,531] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.075,714] <inf> hci_ipc: Received message of 14 bytes.
[00:01:04.135,162] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.135,223] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.135,559] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.135,742] <inf> hci_ipc: Received message of 32 bytes.
[00:01:04.195,190] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.195,251] <inf> hci_ipc: Sent message of 18 bytes.
[00:01:04.195,648] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.195,861] <inf> hci_ipc: Received message of 14 bytes.
[00:01:04.255,187] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.255,249] <inf> hci_ipc: Sent message of 14 bytes.
[00:01:04.255,523] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.255,737] <inf> hci_ipc: Received message of 11 bytes.
[00:01:04.315,216] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.315,307] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.315,582] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.315,765] <inf> hci_ipc: Received message of 25 bytes.
[00:01:04.375,183] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.375,244] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.375,610] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.375,793] <inf> hci_ipc: Received message of 21 bytes.
[00:01:04.435,211] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.435,272] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.435,577] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.435,791] <inf> hci_ipc: Received message of 29 bytes.
[00:01:04.435,852] <inf> bt_ctlr_ull_conn: incoming Tx: count= 8, len= 117, rate= 949 bps.
[00:01:04.495,239] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.495,635] <inf> hci_ipc: Sent message of 14 bytes.
[00:01:04.495,697] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.495,758] <inf> hci_ipc: Received message of 18 bytes.
[00:01:04.495,971] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.496,154] <inf> hci_ipc: Received message of 18 bytes.
[00:01:04.496,337] <inf> hci_ipc: Sent message of 9 bytes.
[00:01:04.555,053] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.555,572] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.555,877] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.556,091] <inf> hci_ipc: Received message of 29 bytes.
[00:01:04.615,234] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.615,325] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.615,600] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.615,783] <inf> hci_ipc: Received message of 14 bytes.
[00:01:04.675,231] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.675,292] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.675,628] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.675,811] <inf> hci_ipc: Received message of 17 bytes.
[00:01:04.735,229] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.735,290] <inf> hci_ipc: Sent message of 14 bytes.
[00:01:04.735,565] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.735,748] <inf> hci_ipc: Received message of 31 bytes.
[00:01:04.795,196] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.795,257] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.795,532] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.795,715] <inf> hci_ipc: Received message of 14 bytes.
[00:01:04.822,784] <inf> hci_ipc: Sent message of 13 bytes.
[00:01:04.839,935] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.847,656] <inf> hci_ipc: Sent message of 14 bytes.
[00:01:04.847,900] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.848,083] <inf> hci_ipc: Received message of 15 bytes.
[00:01:04.862,731] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.862,792] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.863,098] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.863,281] <inf> hci_ipc: Received message of 14 bytes.
[00:01:04.877,716] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.877,807] <inf> hci_ipc: Sent message of 14 bytes.
[00:01:04.878,082] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.878,265] <inf> hci_ipc: Received message of 10 bytes.
[00:01:04.892,730] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.892,791] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.893,096] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.893,280] <inf> hci_ipc: Received message of 25 bytes.
[00:01:04.907,745] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.907,806] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.908,172] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.908,355] <inf> hci_ipc: Received message of 14 bytes.
[00:01:04.922,729] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.922,790] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.923,065] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.923,278] <inf> hci_ipc: Received message of 18 bytes.
[00:01:04.937,744] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.937,805] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.938,079] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.938,262] <inf> hci_ipc: Received message of 14 bytes.
[00:01:04.952,728] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.952,789] <inf> hci_ipc: Sent message of 14 bytes.
[00:01:04.953,033] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.953,247] <inf> hci_ipc: Received message of 15 bytes.
[00:01:04.967,712] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.967,773] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.968,048] <inf> hci_ipc: Received message of 9 bytes.
[00:01:04.968,261] <inf> hci_ipc: Received message of 14 bytes.
[00:01:04.982,696] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:04.982,757] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.983,062] <inf> hci_ipc: Received message of 9 bytes.
--- 2 messages dropped ---
[00:01:04.997,772] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:04.998,046] <inf> hci_ipc: Received message of 9 bytes.
--- 3 messages dropped ---
[00:01:05.013,092] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.013,275] <inf> hci_ipc: Received message of 14 bytes.
--- 3 messages dropped ---
[00:01:05.028,320] <inf> hci_ipc: Received message of 14 bytes.
--- 4 messages dropped ---
[00:01:05.057,739] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:05.057,800] <inf> hci_ipc: Sent message of 16 bytes.
--- 3 messages dropped ---
[00:01:05.072,814] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:05.073,089] <inf> hci_ipc: Received message of 9 bytes.
--- 3 messages dropped ---
[00:01:05.088,043] <inf> hci_ipc: Received message of 9 bytes.
--- 1 messages dropped ---
[00:01:05.103,088] <inf> hci_ipc: Received message of 9 bytes.
--- 2 messages dropped ---
[00:01:05.103,271] <inf> hci_ipc: Received message of 15 bytes.
--- 1 messages dropped ---
[00:01:05.117,797] <inf> hci_ipc: Sent message of 14 bytes.
--- 1 messages dropped ---
[00:01:05.118,255] <inf> hci_ipc: Received message of 15 bytes.
--- 2 messages dropped ---
[00:01:05.133,056] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.133,239] <inf> hci_ipc: Received message of 15 bytes.
[00:01:05.147,705] <inf> hci_ipc: Sent message of 8 bytes.
--- 1 messages dropped ---
[00:01:05.148,101] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.148,284] <inf> hci_ipc: Received message of 14 bytes.
[00:01:05.162,719] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:05.162,780] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:05.163,085] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.163,269] <inf> hci_ipc: Received message of 25 bytes.
[00:01:05.177,703] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:05.177,795] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:05.178,070] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.178,283] <inf> hci_ipc: Received message of 25 bytes.
[00:01:05.192,749] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:05.192,810] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:05.193,115] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.193,328] <inf> hci_ipc: Received message of 25 bytes.
[00:01:05.207,733] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:05.207,824] <inf> hci_ipc: Sent message of 16 bytes.
[00:01:05.208,129] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.208,312] <inf> hci_ipc: Received message of 14 bytes.
[00:01:05.222,473] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:05.230,194] <inf> hci_ipc: Sent message of 14 bytes.
[00:01:05.230,438] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.230,621] <inf> hci_ipc: Received message of 15 bytes.
[00:01:05.244,964] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:05.252,777] <inf> hci_ipc: Sent message of 14 bytes.
[00:01:05.252,960] <inf> hci_ipc: Received message of 18 bytes.
[00:01:05.253,173] <inf> hci_ipc: Sent message of 9 bytes.
[00:01:05.332,794] <inf> hci_ipc: Sent message of 13 bytes.
[00:01:05.425,567] <inf> hci_ipc: Sent message of 12 bytes.
[00:01:05.425,781] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.425,964] <inf> hci_ipc: Received message of 12 bytes.
[00:01:05.485,107] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:05.485,626] <inf> hci_ipc: Sent message of 12 bytes.
[00:01:05.485,900] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.486,083] <inf> hci_ipc: Received message of 41 bytes.
[00:01:05.486,175] <inf> bt_ctlr_ull_conn: incoming Tx: count= 34, len= 446, rate= 3603 bps.
[00:01:05.545,166] <inf> hci_ipc: Sent message of 14 bytes.
[00:01:05.605,255] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:05.605,316] <inf> hci_ipc: Sent message of 12 bytes.
[00:01:05.605,621] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.605,804] <inf> hci_ipc: Received message of 14 bytes.
[00:01:05.665,252] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:05.665,344] <inf> hci_ipc: Sent message of 12 bytes.
[00:01:05.665,618] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.665,802] <inf> hci_ipc: Received message of 41 bytes.
[00:01:05.725,219] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:05.725,311] <inf> hci_ipc: Sent message of 12 bytes.
[00:01:05.725,585] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.725,769] <inf> hci_ipc: Received message of 14 bytes.
[00:01:05.785,278] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:05.785,339] <inf> hci_ipc: Sent message of 14 bytes.
[00:01:05.785,644] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.785,827] <inf> hci_ipc: Received message of 10 bytes.
[00:01:05.845,275] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:05.845,336] <inf> hci_ipc: Sent message of 12 bytes.
[00:01:05.845,611] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.845,825] <inf> hci_ipc: Received message of 14 bytes.
[00:01:05.905,242] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:05.905,303] <inf> hci_ipc: Sent message of 12 bytes.
[00:01:05.905,578] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.905,761] <inf> hci_ipc: Received message of 14 bytes.
[00:01:05.965,240] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:05.965,332] <inf> hci_ipc: Sent message of 14 bytes.
[00:01:05.965,606] <inf> hci_ipc: Received message of 9 bytes.
[00:01:05.965,789] <inf> hci_ipc: Received message of 10 bytes.
[00:01:06.025,268] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:06.025,360] <inf> hci_ipc: Sent message of 14 bytes.
[00:01:06.025,665] <inf> hci_ipc: Received message of 9 bytes.
[00:01:06.025,848] <inf> hci_ipc: Received message of 10 bytes.
[00:01:06.085,296] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:06.085,357] <inf> hci_ipc: Sent message of 14 bytes.
[00:01:06.085,632] <inf> hci_ipc: Received message of 9 bytes.
[00:01:06.085,845] <inf> hci_ipc: Received message of 10 bytes.
[00:01:06.145,233] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:06.145,324] <inf> hci_ipc: Sent message of 14 bytes.
[00:01:06.145,599] <inf> hci_ipc: Received message of 9 bytes.
[00:01:06.145,812] <inf> hci_ipc: Received message of 10 bytes.
[00:01:06.205,291] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:06.205,383] <inf> hci_ipc: Sent message of 12 bytes.
[00:01:06.205,657] <inf> hci_ipc: Received message of 9 bytes.
[00:01:06.205,841] <inf> hci_ipc: Received message of 12 bytes.
[00:01:06.265,289] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:06.265,350] <inf> hci_ipc: Sent message of 12 bytes.
[00:01:06.265,655] <inf> hci_ipc: Received message of 9 bytes.
[00:01:06.265,838] <inf> hci_ipc: Received message of 12 bytes.
[00:01:06.325,256] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:06.325,317] <inf> hci_ipc: Sent message of 12 bytes.
[00:01:06.325,592] <inf> hci_ipc: Received message of 9 bytes.
[00:01:06.325,805] <inf> hci_ipc: Received message of 12 bytes.
[00:01:06.385,009] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:06.633,605] <inf> hci_ipc: Received message of 18 bytes.
[00:01:06.633,880] <inf> hci_ipc: Sent message of 7 bytes.
[00:01:06.952,911] <inf> hci_ipc: Sent message of 13 bytes.
[00:01:12.325,592] <inf> hci_ipc: Sent message of 42 bytes.
[00:01:12.326,568] <inf> hci_ipc: Received message of 9 bytes.
[00:01:12.326,812] <inf> hci_ipc: Received message of 17 bytes.
[00:01:12.326,904] <inf> bt_ctlr_ull_conn: force_md_cnt: old= 0, new= 140.
[00:01:12.326,965] <inf> bt_ctlr_ull_conn: incoming Tx: count= 14, len= 154, rate= 1467 bps.
[00:01:12.327,087] <inf> hci_ipc: Received message of 56 bytes.
[00:01:12.327,880] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:12.328,521] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:12.355,560] <inf> hci_ipc: Sent message of 30 bytes.
[00:01:12.355,987] <inf> hci_ipc: Received message of 9 bytes.
[00:01:12.356,262] <inf> hci_ipc: Received message of 17 bytes.
[00:01:12.356,475] <inf> hci_ipc: Received message of 29 bytes.
[00:01:12.357,055] <inf> hci_ipc: Sent message [00:01:12.357,543] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:12.385,528] <inf> hci_ipc: Sent message of 23 bytes.
[00:01:12.386,718] <inf> hci_ipc: Received message of 9 bytes.
[00:01:12.387,023] <inf> hci_ipc: Received message of 17 bytes.
[00:01:12.387,237] <inf> hci_ipc: Received message of 24 bytes.
[00:01:12.387,817] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:12.388,275] <inf> hci_ipc: Sent message of 8 bytes.
[00:01:12.394,012] <inf> hci_ipc: Sent message of 10 bytes.
[00:01:12.394,256] <inf> hci_ipc: Received message of 6 bytes.
[00:01:12.394,531] <inf> hci_ipc: Sent message of 7 bytes.
[00:01:12.428,070] <inf> hci_ipc: Sent message of 32 bytes.
[00:01:12.428,283] <inf> hci_ipc: Received message of 17 bytes.
[00:01:12.428,527] <inf> hci_ipc: Sent message of 9 bytes.
[00:01:12.428,833] <inf> hci_ipc: Received message of 24 bytes.
[00:01:12.445,922] <inf> hci_ipc: Sent message of 8 bytes.
ASSERTION FAIL [net_buf_simple_headroom(buf) >= len] @ WEST_TOPDIR/zephyr/subsys/net/buf_simple.c:341
[00:01:12.447,967] <err> os: r0/a1:  0x00000004  r1/a2:  0x00000000  r2/a3:  0x00000010
[00:01:12.447,967] <err> os: r3/a4:  0x00000004 r12/ip:  0x2100b940 r14/lr:  0x01026f85
[00:01:12.447,998] <err> os:  xpsr:  0x29000000
[00:01:12.447,998] <err> os: Faulting instruction address (r15/pc): 0x01036956
[00:01:12.448,059] <err> os: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0
[00:01:12.448,089] <err> os: Current thread: 0x21000e80 (unknown)
[00:01:12.595,428] <err> os: Halting system

@cvinayak
Copy link
Contributor

please cherry-pick e8c5405 and give a try?

git cherry-pick e8c5405609e355cf9483debffbd09844e4c92900

@dev-pac
Copy link
Author

dev-pac commented Jan 10, 2025

I get this error when stream is started:

ASSERTION FAIL [cis_lll] @ WEST_TOPDIR/zephyr/subsys/bluetooth/controller/ll_sw/nordic/lll/lll_peripheral_iso.c:174

@cvinayak
Copy link
Contributor

Ok, it is bug in the Controller implementation exposed due to a possible race during termination of ACL and CIG. This github issue will need some planning effort to submit a fix.

@cvinayak cvinayak assigned cvinayak and unassigned jhedberg and alwa-nordic Jan 10, 2025
@cvinayak cvinayak added area: Bluetooth ISO Bluetooth LE Isochronous Channels priority: low Low impact/importance bug labels Jan 10, 2025
@dev-pac
Copy link
Author

dev-pac commented Jan 10, 2025

Ok thanks

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area: Bluetooth Controller area: Bluetooth ISO Bluetooth LE Isochronous Channels area: Bluetooth bug The issue is a bug, or the PR is fixing a bug priority: low Low impact/importance bug
Projects
None yet
Development

No branches or pull requests

5 participants