Enabling an advertising set already enabled trigger the HCI error command disallowed

When Enabling an advertising set already enabled on the Softdevice Controller, the HCI error command disallowed is produced when according to the BLE specification 6.0 it should be possible without any error.

Vol4 Part E Chapter 7.8.56

The current version of the doftdevice controller is:

`- name: nrfxlib`
	`url: github.com/.../sdk-nrfxlib`
	`revision: 342901a77938defa0edfa045f9bd90350958ae90`
	`path: _nordic_sdk/nrfxlib`

nordic_advertising_enable_issue.btt

Parents

0 Cyril Praz 4 hours ago

Hello,

You can find here a project with the minimum of dependencies possible exposing the issue of the ticket: Cyrillius/NordicTestBench: A simple project in order to test the Softdevice Controller from Nordic in standalone

The output of the test should look like this:

2025-06-19 08:18:25,334 - twister - DEBUG - DEVICE: *** Booting nRF Connect SDK v2.9.2-4ab7b98fc76f ***
2025-06-19 08:18:25,338 - twister - DEBUG - DEVICE: *** Using Zephyr OS v3.7.99-aa34a5632971 ***
2025-06-19 08:18:25,341 - twister - DEBUG - DEVICE: Running TESTSUITE sdc_testbench
2025-06-19 08:18:25,348 - twister - DEBUG - DEVICE: ===================================================================
2025-06-19 08:18:25,354 - twister - DEBUG - DEVICE: [00:00:00.261,413] [0m<dbg> sdc_testbench: setup: enable bluetooth[0m
2025-06-19 08:18:25,360 - twister - DEBUG - DEVICE: [00:00:00.261,474] [0m<dbg> bt_hci_driver: bt_ipc_open: [0m
2025-06-19 08:18:25,367 - twister - DEBUG - DEVICE: [00:00:00.271,453] [0m<inf> bt_hci_raw: Bluetooth enabled in RAW mode[0m
2025-06-19 08:18:25,375 - twister - DEBUG - DEVICE: [00:00:00.271,484] [0m<dbg> sdc_testbench: setup: reset bluetooth controller stack[0m
2025-06-19 08:18:25,383 - twister - DEBUG - DEVICE: [00:00:00.271,484] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0x0c03 param_len 0[0m
2025-06-19 08:18:25,391 - twister - DEBUG - DEVICE: [00:00:00.271,514] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:25,399 - twister - DEBUG - DEVICE: [00:00:00.271,545] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 3[0m
2025-06-19 08:18:25,406 - twister - DEBUG - DEVICE: [00:00:00.271,575] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:25,416 - twister - DEBUG - DEVICE: 01 03 0c 00                                      |....             [0m
2025-06-19 08:18:25,423 - twister - DEBUG - DEVICE: [00:00:00.272,094] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:25,433 - twister - DEBUG - DEVICE: 04 0e 04 01 03 0c 00                             |.......          [0m
2025-06-19 08:18:25,439 - twister - DEBUG - DEVICE: [00:00:00.272,125] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 4[0m
2025-06-19 08:18:25,447 - twister - DEBUG - DEVICE: [00:00:00.272,155] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20008298)[0m
2025-06-19 08:18:25,454 - twister - DEBUG - DEVICE: [00:00:00.272,216] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:25,464 - twister - DEBUG - DEVICE: 0e 04 01 03 0c 00                                |......           [0m
2025-06-19 08:18:25,471 - twister - DEBUG - DEVICE: [00:00:00.272,277] [0m<dbg> sdc_testbench: setup: set bd address[0m
2025-06-19 08:18:25,479 - twister - DEBUG - DEVICE: [00:00:00.272,277] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0xfc06 param_len 6[0m
2025-06-19 08:18:25,487 - twister - DEBUG - DEVICE: [00:00:00.272,308] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:25,495 - twister - DEBUG - DEVICE: [00:00:00.272,338] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 9[0m
2025-06-19 08:18:25,502 - twister - DEBUG - DEVICE: [00:00:00.272,369] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:25,512 - twister - DEBUG - DEVICE: 01 06 fc 06 a5 00 45 32  3f 31                   |......E2 ?1      [0m
2025-06-19 08:18:25,518 - twister - DEBUG - DEVICE: [00:00:00.272,827] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:25,528 - twister - DEBUG - DEVICE: 04 0e 04 01 06 fc 00                             |.......          [0m
2025-06-19 08:18:25,535 - twister - DEBUG - DEVICE: [00:00:00.272,827] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 4[0m
2025-06-19 08:18:25,543 - twister - DEBUG - DEVICE: [00:00:00.272,857] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20008298)[0m
2025-06-19 08:18:25,550 - twister - DEBUG - DEVICE: [00:00:00.272,918] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:25,560 - twister - DEBUG - DEVICE: 0e 04 01 06 fc 00                                |......           [0m
2025-06-19 08:18:25,569 - twister - DEBUG - DEVICE: [00:00:00.272,979] [0m<dbg> sdc_testbench: setup: add dummy entry into the resolving list[0m
2025-06-19 08:18:25,578 - twister - DEBUG - DEVICE: [00:00:00.272,979] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0x2027 param_len 39[0m
2025-06-19 08:18:25,585 - twister - DEBUG - DEVICE: [00:00:00.273,010] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:25,593 - twister - DEBUG - DEVICE: [00:00:00.273,040] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 42[0m
2025-06-19 08:18:25,600 - twister - DEBUG - DEVICE: [00:00:00.273,071] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:25,610 - twister - DEBUG - DEVICE: 01 27 20 27 00 00 00 00  00 00 00 00 00 00 00 00 |.' '.... ........
2025-06-19 08:18:25,621 - twister - DEBUG - DEVICE: 00 00 00 00 00 00 00 00  00 00 00 e1 86 e3 93 77 |........ .......w
2025-06-19 08:18:25,631 - twister - DEBUG - DEVICE: 5b 5f 1c 91 61 4b e3 78  3c d5 3c                |[_..aK.x <.<     [0m
2025-06-19 08:18:25,637 - twister - DEBUG - DEVICE: [00:00:00.273,590] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:25,647 - twister - DEBUG - DEVICE: 04 0e 04 01 27 20 00                             |....' .          [0m
2025-06-19 08:18:25,654 - twister - DEBUG - DEVICE: [00:00:00.273,620] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 4[0m
2025-06-19 08:18:25,662 - twister - DEBUG - DEVICE: [00:00:00.273,651] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20008298)[0m
2025-06-19 08:18:25,668 - twister - DEBUG - DEVICE: [00:00:00.273,681] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:25,679 - twister - DEBUG - DEVICE: 0e 04 01 27 20 00                                |...' .           [0m
2025-06-19 08:18:25,686 - twister - DEBUG - DEVICE: [00:00:00.273,742] [0m<dbg> sdc_testbench: setup: enable address resolution[0m
2025-06-19 08:18:25,695 - twister - DEBUG - DEVICE: [00:00:00.273,773] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0x202d param_len 1[0m
2025-06-19 08:18:25,702 - twister - DEBUG - DEVICE: [00:00:00.273,803] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:25,710 - twister - DEBUG - DEVICE: [00:00:00.273,803] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 4[0m
2025-06-19 08:18:25,717 - twister - DEBUG - DEVICE: [00:00:00.273,834] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:25,728 - twister - DEBUG - DEVICE: 01 2d 20 01 01                                   |.- ..            [0m
2025-06-19 08:18:25,734 - twister - DEBUG - DEVICE: [00:00:00.274,291] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:25,744 - twister - DEBUG - DEVICE: 04 0e 04 01 2d 20 00                             |....- .          [0m
2025-06-19 08:18:25,750 - twister - DEBUG - DEVICE: [00:00:00.274,322] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 4[0m
2025-06-19 08:18:25,759 - twister - DEBUG - DEVICE: [00:00:00.274,353] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20008298)[0m
2025-06-19 08:18:25,765 - twister - DEBUG - DEVICE: [00:00:00.274,383] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:25,775 - twister - DEBUG - DEVICE: 0e 04 01 2d 20 00                                |...- .           [0m
2025-06-19 08:18:25,779 - twister - DEBUG - DEVICE: START - test_enabling_advertising_twice
2025-06-19 08:18:25,788 - twister - DEBUG - DEVICE: [00:00:00.274,505] [0m<inf> sdc_testbench: Test enabling advertising twice should be ok[0m
2025-06-19 08:18:25,799 - twister - DEBUG - DEVICE: [00:00:00.274,505] [0m<dbg> sdc_testbench: sdc_testbench_test_enabling_advertising_twice: set advertising parameter[0m
2025-06-19 08:18:25,807 - twister - DEBUG - DEVICE: [00:00:00.274,536] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0x2036 param_len 25[0m
2025-06-19 08:18:25,814 - twister - DEBUG - DEVICE: [00:00:00.274,566] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:25,822 - twister - DEBUG - DEVICE: [00:00:00.274,627] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 28[0m
2025-06-19 08:18:25,830 - twister - DEBUG - DEVICE: [00:00:00.274,658] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:25,840 - twister - DEBUG - DEVICE: 01 36 20 19 01 13 00 a8  00 00 a8 00 00 07 00 00 |.6 ..... ........
2025-06-19 08:18:25,851 - twister - DEBUG - DEVICE: 00 00 00 00 00 00 00 7f  01 00 02 00 00          |........ .....   [0m
2025-06-19 08:18:25,857 - twister - DEBUG - DEVICE: [00:00:00.275,146] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:25,867 - twister - DEBUG - DEVICE: 04 0e 05 01 36 20 00 00                          |....6 ..         [0m
2025-06-19 08:18:25,874 - twister - DEBUG - DEVICE: [00:00:00.275,177] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 5[0m
2025-06-19 08:18:25,882 - twister - DEBUG - DEVICE: [00:00:00.275,207] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20008298)[0m
2025-06-19 08:18:25,892 - twister - DEBUG - DEVICE: [00:00:00.275,268] [0m<dbg> sdc_testbench: sdc_testbench_test_enabling_advertising_twice: set advertising data[0m
2025-06-19 08:18:25,901 - twister - DEBUG - DEVICE: [00:00:00.275,268] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0x2037 param_len 12[0m
2025-06-19 08:18:25,908 - twister - DEBUG - DEVICE: [00:00:00.275,299] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:25,916 - twister - DEBUG - DEVICE: [00:00:00.275,329] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 15[0m
2025-06-19 08:18:25,924 - twister - DEBUG - DEVICE: [00:00:00.275,360] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:25,934 - twister - DEBUG - DEVICE: 01 37 20 0c 01 03 01 08  02 01 08 04 ff 82 02 00 |.7 ..... ........[0m
2025-06-19 08:18:25,941 - twister - DEBUG - DEVICE: [00:00:00.275,451] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:25,951 - twister - DEBUG - DEVICE: 00 00 00 00 00 00 00                             |.......          [0m
2025-06-19 08:18:25,957 - twister - DEBUG - DEVICE: [00:00:00.275,817] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:25,967 - twister - DEBUG - DEVICE: 04 0e 04 01 37 20 00                             |....7 .          [0m
2025-06-19 08:18:25,974 - twister - DEBUG - DEVICE: [00:00:00.275,848] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 4[0m
2025-06-19 08:18:25,982 - twister - DEBUG - DEVICE: [00:00:00.275,878] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20008298)[0m
2025-06-19 08:18:25,993 - twister - DEBUG - DEVICE: [00:00:00.275,909] [0m<dbg> sdc_testbench: sdc_testbench_test_enabling_advertising_twice: enable advertising first time[0m
2025-06-19 08:18:26,002 - twister - DEBUG - DEVICE: [00:00:00.275,939] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0x2039 param_len 6[0m
2025-06-19 08:18:26,009 - twister - DEBUG - DEVICE: [00:00:00.275,970] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:26,017 - twister - DEBUG - DEVICE: [00:00:00.275,970] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 9[0m
2025-06-19 08:18:26,024 - twister - DEBUG - DEVICE: [00:00:00.276,000] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:26,035 - twister - DEBUG - DEVICE: 01 39 20 06 01 01 01 f4  01 00                   |.9 ..... ..      [0m
2025-06-19 08:18:26,041 - twister - DEBUG - DEVICE: [00:00:00.276,092] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:26,051 - twister - DEBUG - DEVICE: 00 00 00 00 00 00                                |......           [0m
2025-06-19 08:18:26,058 - twister - DEBUG - DEVICE: [00:00:00.276,580] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:26,068 - twister - DEBUG - DEVICE: 04 0e 04 01 39 20 00                             |....9 .          [0m
2025-06-19 08:18:26,075 - twister - DEBUG - DEVICE: [00:00:00.276,611] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 4[0m
2025-06-19 08:18:26,083 - twister - DEBUG - DEVICE: [00:00:00.276,641] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20008298)[0m
2025-06-19 08:18:26,089 - twister - DEBUG - DEVICE: [00:00:00.276,733] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:26,099 - twister - DEBUG - DEVICE: 00 00 00 00 00 00                                |......           [0m
2025-06-19 08:18:26,355 - twister - DEBUG - DEVICE: [00:00:01.276,763] [0m<dbg> sdc_testbench: sdc_testbench_test_enabling_advertising_twice: enable advertising second time[0m
2025-06-19 08:18:26,364 - twister - DEBUG - DEVICE: [00:00:01.276,794] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0x2039 param_len 6[0m
2025-06-19 08:18:26,372 - twister - DEBUG - DEVICE: [00:00:01.276,824] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:26,379 - twister - DEBUG - DEVICE: [00:00:01.276,855] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 9[0m
2025-06-19 08:18:26,387 - twister - DEBUG - DEVICE: [00:00:01.276,885] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:26,397 - twister - DEBUG - DEVICE: 01 39 20 06 01 01 01 f4  01 00                   |.9 ..... ..      [0m
2025-06-19 08:18:26,403 - twister - DEBUG - DEVICE: [00:00:01.277,374] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:26,413 - twister - DEBUG - DEVICE: 04 0e 04 01 39 20 0c                             |....9 .          [0m
2025-06-19 08:18:26,420 - twister - DEBUG - DEVICE: [00:00:01.277,404] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 4[0m
2025-06-19 08:18:26,428 - twister - DEBUG - DEVICE: [00:00:01.277,435] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20008298)[0m
2025-06-19 08:18:26,438 - twister - DEBUG - DEVICE: Assertion failed at CMAKE_SOURCE_DIR/src/main.c:59: expect_receive: exp_data not equal to rx_msg->data
2025-06-19 08:18:26,445 - twister - DEBUG - DEVICE: [00:00:01.277,587] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:26,456 - twister - DEBUG - DEVICE: 0e 04 01 39 20 0c                                |...9 .           [0m
2025-06-19 08:18:26,461 - twister - DEBUG - DEVICE: FAIL - test_enabling_advertising_twice in 1.004 seconds
2025-06-19 08:18:26,467 - twister - DEBUG - DEVICE: ===================================================================
2025-06-19 08:18:26,469 - twister - DEBUG - DEVICE: TESTSUITE sdc_testbench failed.
2025-06-19 08:18:26,478 - twister - DEBUG - DEVICE: [00:00:01.377,807] [0m<dbg> sdc_testbench: teardown: reset bluetooth controller stack[0m
2025-06-19 08:18:26,487 - twister - DEBUG - DEVICE: [00:00:01.377,838] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0x0c03 param_len 0[0m
2025-06-19 08:18:26,495 - twister - DEBUG - DEVICE: [00:00:01.377,868] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:26,502 - twister - DEBUG - DEVICE: [00:00:01.377,868] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 3[0m
2025-06-19 08:18:26,510 - twister - DEBUG - DEVICE: [00:00:01.377,899] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:26,520 - twister - DEBUG - DEVICE: 01 03 0c 00                                      |....             [0m
2025-06-19 08:18:26,526 - twister - DEBUG - DEVICE: [00:00:01.378,479] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:26,536 - twister - DEBUG - DEVICE: 04 0e 04 01 03 0c 00                             |.......          [0m
2025-06-19 08:18:26,543 - twister - DEBUG - DEVICE: [00:00:01.378,509] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 4[0m
2025-06-19 08:18:26,551 - twister - DEBUG - DEVICE: [00:00:01.378,570] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x200082b4)[0m
2025-06-19 08:18:26,558 - twister - DEBUG - DEVICE: [00:00:01.378,601] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:26,568 - twister - DEBUG - DEVICE: 0e 04 01 03 0c 00                                |......           [0m
2025-06-19 08:18:26,571 - twister - DEBUG - DEVICE: ------ TESTSUITE SUMMARY START ------
2025-06-19 08:18:27,595 - twister - DEBUG - DEVICE: SUITE FAIL -   0.00% [sdc_testbench]: pass = 0, fail = 1, skip = 0, total = 1 duration = 1.004 seconds
2025-06-19 08:18:28,614 - twister - DEBUG - DEVICE: - FAIL - [sdc_testbench.test_enabling_advertising_twice] duration = 1.004 seconds
2025-06-19 08:18:30,650 - twister - DEBUG - DEVICE: ------ TESTSUITE SUMMARY END ------
2025-06-19 08:18:31,673 - twister - DEBUG - DEVICE: ===================================================================
2025-06-19 08:18:31,675 - twister - DEBUG - DEVICE: PROJECT EXECUTION FAILED

Reply

0 Cyril Praz 4 hours ago

The output of the test should look like this:

2025-06-19 08:18:25,334 - twister - DEBUG - DEVICE: *** Booting nRF Connect SDK v2.9.2-4ab7b98fc76f ***
2025-06-19 08:18:25,338 - twister - DEBUG - DEVICE: *** Using Zephyr OS v3.7.99-aa34a5632971 ***
2025-06-19 08:18:25,341 - twister - DEBUG - DEVICE: Running TESTSUITE sdc_testbench
2025-06-19 08:18:25,348 - twister - DEBUG - DEVICE: ===================================================================
2025-06-19 08:18:25,354 - twister - DEBUG - DEVICE: [00:00:00.261,413] [0m<dbg> sdc_testbench: setup: enable bluetooth[0m
2025-06-19 08:18:25,360 - twister - DEBUG - DEVICE: [00:00:00.261,474] [0m<dbg> bt_hci_driver: bt_ipc_open: [0m
2025-06-19 08:18:25,367 - twister - DEBUG - DEVICE: [00:00:00.271,453] [0m<inf> bt_hci_raw: Bluetooth enabled in RAW mode[0m
2025-06-19 08:18:25,375 - twister - DEBUG - DEVICE: [00:00:00.271,484] [0m<dbg> sdc_testbench: setup: reset bluetooth controller stack[0m
2025-06-19 08:18:25,383 - twister - DEBUG - DEVICE: [00:00:00.271,484] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0x0c03 param_len 0[0m
2025-06-19 08:18:25,391 - twister - DEBUG - DEVICE: [00:00:00.271,514] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:25,399 - twister - DEBUG - DEVICE: [00:00:00.271,545] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 3[0m
2025-06-19 08:18:25,406 - twister - DEBUG - DEVICE: [00:00:00.271,575] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:25,416 - twister - DEBUG - DEVICE: 01 03 0c 00                                      |....             [0m
2025-06-19 08:18:25,423 - twister - DEBUG - DEVICE: [00:00:00.272,094] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:25,433 - twister - DEBUG - DEVICE: 04 0e 04 01 03 0c 00                             |.......          [0m
2025-06-19 08:18:25,439 - twister - DEBUG - DEVICE: [00:00:00.272,125] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 4[0m
2025-06-19 08:18:25,447 - twister - DEBUG - DEVICE: [00:00:00.272,155] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20008298)[0m
2025-06-19 08:18:25,454 - twister - DEBUG - DEVICE: [00:00:00.272,216] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:25,464 - twister - DEBUG - DEVICE: 0e 04 01 03 0c 00                                |......           [0m
2025-06-19 08:18:25,471 - twister - DEBUG - DEVICE: [00:00:00.272,277] [0m<dbg> sdc_testbench: setup: set bd address[0m
2025-06-19 08:18:25,479 - twister - DEBUG - DEVICE: [00:00:00.272,277] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0xfc06 param_len 6[0m
2025-06-19 08:18:25,487 - twister - DEBUG - DEVICE: [00:00:00.272,308] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:25,495 - twister - DEBUG - DEVICE: [00:00:00.272,338] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 9[0m
2025-06-19 08:18:25,502 - twister - DEBUG - DEVICE: [00:00:00.272,369] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:25,512 - twister - DEBUG - DEVICE: 01 06 fc 06 a5 00 45 32  3f 31                   |......E2 ?1      [0m
2025-06-19 08:18:25,518 - twister - DEBUG - DEVICE: [00:00:00.272,827] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:25,528 - twister - DEBUG - DEVICE: 04 0e 04 01 06 fc 00                             |.......          [0m
2025-06-19 08:18:25,535 - twister - DEBUG - DEVICE: [00:00:00.272,827] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 4[0m
2025-06-19 08:18:25,543 - twister - DEBUG - DEVICE: [00:00:00.272,857] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20008298)[0m
2025-06-19 08:18:25,550 - twister - DEBUG - DEVICE: [00:00:00.272,918] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:25,560 - twister - DEBUG - DEVICE: 0e 04 01 06 fc 00                                |......           [0m
2025-06-19 08:18:25,569 - twister - DEBUG - DEVICE: [00:00:00.272,979] [0m<dbg> sdc_testbench: setup: add dummy entry into the resolving list[0m
2025-06-19 08:18:25,578 - twister - DEBUG - DEVICE: [00:00:00.272,979] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0x2027 param_len 39[0m
2025-06-19 08:18:25,585 - twister - DEBUG - DEVICE: [00:00:00.273,010] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:25,593 - twister - DEBUG - DEVICE: [00:00:00.273,040] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 42[0m
2025-06-19 08:18:25,600 - twister - DEBUG - DEVICE: [00:00:00.273,071] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:25,610 - twister - DEBUG - DEVICE: 01 27 20 27 00 00 00 00  00 00 00 00 00 00 00 00 |.' '.... ........
2025-06-19 08:18:25,621 - twister - DEBUG - DEVICE: 00 00 00 00 00 00 00 00  00 00 00 e1 86 e3 93 77 |........ .......w
2025-06-19 08:18:25,631 - twister - DEBUG - DEVICE: 5b 5f 1c 91 61 4b e3 78  3c d5 3c                |[_..aK.x <.<     [0m
2025-06-19 08:18:25,637 - twister - DEBUG - DEVICE: [00:00:00.273,590] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:25,647 - twister - DEBUG - DEVICE: 04 0e 04 01 27 20 00                             |....' .          [0m
2025-06-19 08:18:25,654 - twister - DEBUG - DEVICE: [00:00:00.273,620] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 4[0m
2025-06-19 08:18:25,662 - twister - DEBUG - DEVICE: [00:00:00.273,651] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20008298)[0m
2025-06-19 08:18:25,668 - twister - DEBUG - DEVICE: [00:00:00.273,681] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:25,679 - twister - DEBUG - DEVICE: 0e 04 01 27 20 00                                |...' .           [0m
2025-06-19 08:18:25,686 - twister - DEBUG - DEVICE: [00:00:00.273,742] [0m<dbg> sdc_testbench: setup: enable address resolution[0m
2025-06-19 08:18:25,695 - twister - DEBUG - DEVICE: [00:00:00.273,773] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0x202d param_len 1[0m
2025-06-19 08:18:25,702 - twister - DEBUG - DEVICE: [00:00:00.273,803] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:25,710 - twister - DEBUG - DEVICE: [00:00:00.273,803] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 4[0m
2025-06-19 08:18:25,717 - twister - DEBUG - DEVICE: [00:00:00.273,834] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:25,728 - twister - DEBUG - DEVICE: 01 2d 20 01 01                                   |.- ..            [0m
2025-06-19 08:18:25,734 - twister - DEBUG - DEVICE: [00:00:00.274,291] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:25,744 - twister - DEBUG - DEVICE: 04 0e 04 01 2d 20 00                             |....- .          [0m
2025-06-19 08:18:25,750 - twister - DEBUG - DEVICE: [00:00:00.274,322] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 4[0m
2025-06-19 08:18:25,759 - twister - DEBUG - DEVICE: [00:00:00.274,353] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20008298)[0m
2025-06-19 08:18:25,765 - twister - DEBUG - DEVICE: [00:00:00.274,383] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:25,775 - twister - DEBUG - DEVICE: 0e 04 01 2d 20 00                                |...- .           [0m
2025-06-19 08:18:25,779 - twister - DEBUG - DEVICE: START - test_enabling_advertising_twice
2025-06-19 08:18:25,788 - twister - DEBUG - DEVICE: [00:00:00.274,505] [0m<inf> sdc_testbench: Test enabling advertising twice should be ok[0m
2025-06-19 08:18:25,799 - twister - DEBUG - DEVICE: [00:00:00.274,505] [0m<dbg> sdc_testbench: sdc_testbench_test_enabling_advertising_twice: set advertising parameter[0m
2025-06-19 08:18:25,807 - twister - DEBUG - DEVICE: [00:00:00.274,536] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0x2036 param_len 25[0m
2025-06-19 08:18:25,814 - twister - DEBUG - DEVICE: [00:00:00.274,566] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:25,822 - twister - DEBUG - DEVICE: [00:00:00.274,627] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 28[0m
2025-06-19 08:18:25,830 - twister - DEBUG - DEVICE: [00:00:00.274,658] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:25,840 - twister - DEBUG - DEVICE: 01 36 20 19 01 13 00 a8  00 00 a8 00 00 07 00 00 |.6 ..... ........
2025-06-19 08:18:25,851 - twister - DEBUG - DEVICE: 00 00 00 00 00 00 00 7f  01 00 02 00 00          |........ .....   [0m
2025-06-19 08:18:25,857 - twister - DEBUG - DEVICE: [00:00:00.275,146] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:25,867 - twister - DEBUG - DEVICE: 04 0e 05 01 36 20 00 00                          |....6 ..         [0m
2025-06-19 08:18:25,874 - twister - DEBUG - DEVICE: [00:00:00.275,177] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 5[0m
2025-06-19 08:18:25,882 - twister - DEBUG - DEVICE: [00:00:00.275,207] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20008298)[0m
2025-06-19 08:18:25,892 - twister - DEBUG - DEVICE: [00:00:00.275,268] [0m<dbg> sdc_testbench: sdc_testbench_test_enabling_advertising_twice: set advertising data[0m
2025-06-19 08:18:25,901 - twister - DEBUG - DEVICE: [00:00:00.275,268] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0x2037 param_len 12[0m
2025-06-19 08:18:25,908 - twister - DEBUG - DEVICE: [00:00:00.275,299] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:25,916 - twister - DEBUG - DEVICE: [00:00:00.275,329] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 15[0m
2025-06-19 08:18:25,924 - twister - DEBUG - DEVICE: [00:00:00.275,360] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:25,934 - twister - DEBUG - DEVICE: 01 37 20 0c 01 03 01 08  02 01 08 04 ff 82 02 00 |.7 ..... ........[0m
2025-06-19 08:18:25,941 - twister - DEBUG - DEVICE: [00:00:00.275,451] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:25,951 - twister - DEBUG - DEVICE: 00 00 00 00 00 00 00                             |.......          [0m
2025-06-19 08:18:25,957 - twister - DEBUG - DEVICE: [00:00:00.275,817] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:25,967 - twister - DEBUG - DEVICE: 04 0e 04 01 37 20 00                             |....7 .          [0m
2025-06-19 08:18:25,974 - twister - DEBUG - DEVICE: [00:00:00.275,848] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 4[0m
2025-06-19 08:18:25,982 - twister - DEBUG - DEVICE: [00:00:00.275,878] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20008298)[0m
2025-06-19 08:18:25,993 - twister - DEBUG - DEVICE: [00:00:00.275,909] [0m<dbg> sdc_testbench: sdc_testbench_test_enabling_advertising_twice: enable advertising first time[0m
2025-06-19 08:18:26,002 - twister - DEBUG - DEVICE: [00:00:00.275,939] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0x2039 param_len 6[0m
2025-06-19 08:18:26,009 - twister - DEBUG - DEVICE: [00:00:00.275,970] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:26,017 - twister - DEBUG - DEVICE: [00:00:00.275,970] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 9[0m
2025-06-19 08:18:26,024 - twister - DEBUG - DEVICE: [00:00:00.276,000] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:26,035 - twister - DEBUG - DEVICE: 01 39 20 06 01 01 01 f4  01 00                   |.9 ..... ..      [0m
2025-06-19 08:18:26,041 - twister - DEBUG - DEVICE: [00:00:00.276,092] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:26,051 - twister - DEBUG - DEVICE: 00 00 00 00 00 00                                |......           [0m
2025-06-19 08:18:26,058 - twister - DEBUG - DEVICE: [00:00:00.276,580] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:26,068 - twister - DEBUG - DEVICE: 04 0e 04 01 39 20 00                             |....9 .          [0m
2025-06-19 08:18:26,075 - twister - DEBUG - DEVICE: [00:00:00.276,611] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 4[0m
2025-06-19 08:18:26,083 - twister - DEBUG - DEVICE: [00:00:00.276,641] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20008298)[0m
2025-06-19 08:18:26,089 - twister - DEBUG - DEVICE: [00:00:00.276,733] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:26,099 - twister - DEBUG - DEVICE: 00 00 00 00 00 00                                |......           [0m
2025-06-19 08:18:26,355 - twister - DEBUG - DEVICE: [00:00:01.276,763] [0m<dbg> sdc_testbench: sdc_testbench_test_enabling_advertising_twice: enable advertising second time[0m
2025-06-19 08:18:26,364 - twister - DEBUG - DEVICE: [00:00:01.276,794] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0x2039 param_len 6[0m
2025-06-19 08:18:26,372 - twister - DEBUG - DEVICE: [00:00:01.276,824] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:26,379 - twister - DEBUG - DEVICE: [00:00:01.276,855] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 9[0m
2025-06-19 08:18:26,387 - twister - DEBUG - DEVICE: [00:00:01.276,885] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:26,397 - twister - DEBUG - DEVICE: 01 39 20 06 01 01 01 f4  01 00                   |.9 ..... ..      [0m
2025-06-19 08:18:26,403 - twister - DEBUG - DEVICE: [00:00:01.277,374] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:26,413 - twister - DEBUG - DEVICE: 04 0e 04 01 39 20 0c                             |....9 .          [0m
2025-06-19 08:18:26,420 - twister - DEBUG - DEVICE: [00:00:01.277,404] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 4[0m
2025-06-19 08:18:26,428 - twister - DEBUG - DEVICE: [00:00:01.277,435] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x20008298)[0m
2025-06-19 08:18:26,438 - twister - DEBUG - DEVICE: Assertion failed at CMAKE_SOURCE_DIR/src/main.c:59: expect_receive: exp_data not equal to rx_msg->data
2025-06-19 08:18:26,445 - twister - DEBUG - DEVICE: [00:00:01.277,587] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:26,456 - twister - DEBUG - DEVICE: 0e 04 01 39 20 0c                                |...9 .           [0m
2025-06-19 08:18:26,461 - twister - DEBUG - DEVICE: FAIL - test_enabling_advertising_twice in 1.004 seconds
2025-06-19 08:18:26,467 - twister - DEBUG - DEVICE: ===================================================================
2025-06-19 08:18:26,469 - twister - DEBUG - DEVICE: TESTSUITE sdc_testbench failed.
2025-06-19 08:18:26,478 - twister - DEBUG - DEVICE: [00:00:01.377,807] [0m<dbg> sdc_testbench: teardown: reset bluetooth controller stack[0m
2025-06-19 08:18:26,487 - twister - DEBUG - DEVICE: [00:00:01.377,838] [0m<dbg> sdc_testbench: bt_hci_cmd_create: opcode 0x0c03 param_len 0[0m
2025-06-19 08:18:26,495 - twister - DEBUG - DEVICE: [00:00:01.377,868] [0m<dbg> sdc_testbench: bt_hci_cmd_create: buf 0x20006a68[0m
2025-06-19 08:18:26,502 - twister - DEBUG - DEVICE: [00:00:01.377,868] [0m<dbg> bt_hci_driver: bt_ipc_send: buf 0x20006a68 type 0 len 3[0m
2025-06-19 08:18:26,510 - twister - DEBUG - DEVICE: [00:00:01.377,899] [0m<dbg> bt_hci_driver: bt_ipc_send: Final HCI buffer:
2025-06-19 08:18:26,520 - twister - DEBUG - DEVICE: 01 03 0c 00                                      |....             [0m
2025-06-19 08:18:26,526 - twister - DEBUG - DEVICE: [00:00:01.378,479] [0m<dbg> bt_hci_driver: bt_ipc_rx: ipc data:
2025-06-19 08:18:26,536 - twister - DEBUG - DEVICE: 04 0e 04 01 03 0c 00                             |.......          [0m
2025-06-19 08:18:26,543 - twister - DEBUG - DEVICE: [00:00:01.378,509] [0m<dbg> bt_hci_driver: bt_ipc_evt_recv: len 4[0m
2025-06-19 08:18:26,551 - twister - DEBUG - DEVICE: [00:00:01.378,570] [0m<dbg> bt_hci_driver: bt_ipc_rx: Calling bt_recv(0x200082b4)[0m
2025-06-19 08:18:26,558 - twister - DEBUG - DEVICE: [00:00:01.378,601] [0m<dbg> bt_hci_driver: bt_ipc_rx: RX buf payload:
2025-06-19 08:18:26,568 - twister - DEBUG - DEVICE: 0e 04 01 03 0c 00                                |......           [0m
2025-06-19 08:18:26,571 - twister - DEBUG - DEVICE: ------ TESTSUITE SUMMARY START ------
2025-06-19 08:18:27,595 - twister - DEBUG - DEVICE: SUITE FAIL -   0.00% [sdc_testbench]: pass = 0, fail = 1, skip = 0, total = 1 duration = 1.004 seconds
2025-06-19 08:18:28,614 - twister - DEBUG - DEVICE: - FAIL - [sdc_testbench.test_enabling_advertising_twice] duration = 1.004 seconds
2025-06-19 08:18:30,650 - twister - DEBUG - DEVICE: ------ TESTSUITE SUMMARY END ------
2025-06-19 08:18:31,673 - twister - DEBUG - DEVICE: ===================================================================
2025-06-19 08:18:31,675 - twister - DEBUG - DEVICE: PROJECT EXECUTION FAILED

Children

0 Edvin 1 hour ago in reply to Cyril Praz

Thank you!

You are correct. I discussed this with our softdevice controller team now, and they say that it is indeed not following the specification.

I have created an internal ticket, where they will look into it, but it does require a patch in the softdevice controller, so a fix will be implemented in a future release, but not the current one.

In the meantime, as a workaround, you need to disable that specific advertising before you restart it.

Again, thank you for reporting this bug!

Best regards,

Edvin
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel
0 Cyril Praz 1 hour ago in reply to Edvin

Thanks for you reactivity. Currently we are doing what you are proposing.

Let me know when this fix will be released.
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel