Nimble HCI wait for ack returned 19 (EHM-118)

[lisuchun6556]

Checklist

• Checked the issue tracker for similar issues to ensure this is not a duplicate
• Read the documentation to confirm the issue is not addressed there and your configuration is set correctly
• Tested with the latest version to ensure the issue hasn't been fixed

How often does this bug occurs?

always

Expected behavior

ESP32-P4 + ESP32-C5 SPI communication, using the NimBLE component for BLE.
Expected behavior: BLE advertising works correctly

Actual behavior (suspected bug)

when slave version > 2.5.1 (2.5.2-2.6.1)
nimble hci communication timeout

Error logs or terminal output

slave log:
[10:59:13.602]收←◆ESP-ROM:esp32c5-eco2-2025
[10:59:13.702]收←◆麰SP-ROM:esp32c5-eco2-20250121
Build:Jan 21 2025
rst:0x1 (POWERON),boot:0x1c (SPI_FAST_FLASH_BOOT)
SPI mode:DIO, clock div:1
load:0x408556b0,len:0x183c
load:0x4084bba0,len:0x103c
load:0x4084e5a0,len:0x3a0c
entry 0x4084bbaa
I (23) boot: ESP-IDF v5.5.1-dirty 2nd stage bootloader
I (24) boot: compile time Oct 20 2025 10:25:16
I (24) boot: chip revision: v1.0
I (25) boot: efuse block revision: v0.2
I (28) qio_mode: Enabling default flash chip QIO
I (32) boot.esp32c5: SPI Speed      : 80MHz
I (36) boot.esp32c5: SPI Mode       : QIO
I (40) boot.esp32c5: SPI Flash Size : 4MB
I (43) boot: Enabling RNG early entropy source...
I (48) boot: Partition Table:
I (50) boot: ## Label            Usage          Type ST Offset   Length
I (57) boot:  0 esp_secure_cert  unknown          3f 06 0000d000 00002000
I (63) boot:  1 nvs_key          NVS keys         01 04 0000f000 00001000
I (70) boot:  2 nvs              WiFi data        01 02 00010000 00006000
I (76) boot:  3 otadata          OTA data         01 00 00016000 00002000
I (83) boot:  4 phy_init         RF data          01 01 00018000 00001000
I (89) boot:  5 ota_0            OTA app          00 10 00020000 001e0000
I (96) boot:  6 ota_1            OTA app          00 11 00200000 001e0000
I (102) boot:  7 reserved         unknown          06 06 003e0000 0001a000
I (109) boot:  8 fctry            WiFi data        01 02 003fa000 00006000
I (116) boot: End of partition table
I (119) esp_image: segment 0: paddr=00020020 vaddr=420e0020 size=37e18h (228888) map

[10:59:13.872]收←◆I (164) esp_image: segment 1: paddr=00057e40 vaddr=40800000 size=081d8h ( 33240) load
I (171) esp_image: segment 2: paddr=00060020 vaddr=42000020 size=d7164h (880996) map

[10:59:14.025]收←◆I (315) esp_image: segment 3: paddr=0013718c vaddr=408081d8 size=10d98h ( 69016) load
I (329) esp_image: segment 4: paddr=00147f2c vaddr=40818f80 size=04004h ( 16388) load
I (337) boot: Loaded app from partition at offset 0x20000
I (337) boot: Disabling RNG early entropy source...
I (348) MSPI Timing: tuning success, best point is index 4
I (348) MSPI Timing: Flash timing tuning index: 4
I (348) cpu_start: Unicore app
I (372) cpu_start: Pro cpu start user code
I (372) cpu_start: cpu freq: 240000000 Hz
I (372) app_init: Application information:
I (372) app_init: Project name:     network_adapter
I (377) app_init: App version:      015ab30-dirty
I (381) app_init: Compile time:     Oct 20 2025 10:25:07
I (386) app_init: ELF file SHA256:  659e4febf...
I (390) app_init: ESP-IDF:          v5.5.1-dirty
I (395) efuse_init: Min chip rev:     v1.0
I (399) efuse_init: Max chip rev:     v1.99 
I (403) efuse_init: Chip rev:         v1.0
I (406) heap_init: Initializing. RAM available for dynamic allocation:
I (413) heap_init: At 40824500 len 000380A0 (224 KiB): RAM
I (418) heap_init: At 4085C5A0 len 00002F58 (11 KiB): RAM
I (423) heap_init: At 50000000 len 00003FE8 (15 KiB): RTCRAM
I (429) spi_flash: detected chip: generic
I (432) spi_flash: flash io: qio
I (435) sleep_gpio: Configure to isolate all GPIO pins in sleep state
I (441) sleep_gpio: Enable automatic switching of GPIO sleep configuration
I (448) coexist: coex firmware version: b0bcc39

[10:59:14.182]收←◆I (479) coexist: coexist rom version 78e5c6e42
I (479) main_task: Started on CPU0
I (479) main_task: Calling app_main()
I (485) co-pro-main: *********************************************************************
I (486) co-pro-main:                 ESP-Hosted-MCU Slave FW version :: 2.5.2                        
I (495) co-pro-main:                 Transport used :: SPI only                      
I (502) co-pro-main: *********************************************************************
I (510) SPI_DRIVER: Using SPI interface

[10:59:14.242]收←◆I (538) SPI_DRIVER: SPI Ctrl:1 mode: 3, Freq:ConfigAtHost
GPIOs: CLK:6 MOSI:7 MISO:2 CS:10 HS:3 DR:4

I (538) SPI_DRIVER: Hosted SPI queue size: Tx:20 Rx:20
I (541) SPI_DRIVER: SPI post process task started
I (545) co-pro-main: Mandate host wakeup
I (549) co-pro-main: host reset handler task started
I (553) co-pro-main: Supported features are:
I (557) co-pro-main: - WLAN over SPI
I (561) h_bt: - BT/BLE
I (563) h_bt:    - HCI Over SPI
I (565) h_bt:    - BLE only
I (568) co-pro-main: capabilities: 0xe8
I (572) co-pro-main: Supported extended features are:
I (576) h_bt: - BT/BLE (extended)
I (579) co-pro-main: extended capabilities: 0x0
I (584) co-pro-main: host reconfig event
I (587) SPI_DRIVER: Slave chip Id[12]
I (591) main_task: Returned from app_main()

[10:59:14.352]收←◆I (645) co-pro-main: Slave init_config received from host
I (645) co-pro-main: Host capabilities: 44
I (645) co-pro-main: ESP<-Host wifi flow ctl start thres [90%]
I (648) co-pro-main: ESP<-Host wifi flow ctl clear thres [60%]

[10:59:44.250]收←◆I (30545) stats: STA: flw_ctrl(on[0] off[30]) H2S(in[0] out[0] fail[0]) S2H(in[0] out[0]) Ctrl: (in[0] rsp[0] evt[0])
I (30545) stats: Lwip: in[0] slave_out[0] host_out[0] both_out[0]




Host log:
I (370) host_init: ESP Hosted : Host chip_ip[18]
I (394) H_API: ESP-Hosted starting. Hosted_Tasks: prio:23, stack: 5120 RPC_task_stack: 5120
I (412) H_API: ** add_esp_wifi_remote_channels **
I (412) transport: Add ESP-Hosted channel IF[1]: S[0] Tx[0x4000c54c] Rx[0x40020bce]
I (412) transport: Add ESP-Hosted channel IF[2]: S[0] Tx[0x4000c490] Rx[0x40020bce]
spi_mempool_create free:97228 min-free:97228 lfb-def:57344 lfb-8bit:57344

I (413) spi_wrapper: Transport: SPI, Mode:3 Freq:40MHz TxQ:20 RxQ:20
 GPIOs: CLK:18 MOSI:14 MISO:15 CS:19 HS:16 DR:17 SlaveReset:44
I (415) spi: Staring SPI task
I (415) os_wrapper_esp: GPIO [16] configuring as Interrupt
I (415) gpio: GPIO[16]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (416) main_task: Started on CPU0
I (416) os_wrapper_esp: GPIO [17] configuring as Interrupt
I (416) gpio: GPIO[17]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (417) main_task: Calling app_main()
�[5n
 ==============================================================
 |       Steps to test Robot Console                          |
 |                                                            |
 |  1. Print 'help' to gain overview of commands              |
 |  2. conn -c wifi <ssid> <password> //connect wifi          |
 |  3. conn -c wifi clear //for clear wifi                    |
 |  4. conn -c wificmd // add iperf test command              |
 |  5. ota -c fota <url> <size> <sha256> // fota test command |
 |  6. ota -c sota <url> <size> <sha256> // sota test command |
 |  7. ota -c c5 <url> // c5 local ota command                |
 |                                                            |
 ==============================================================


Type 'help' to get the list of commands.
Use UP/DOWN arrows to navigate through command history.
Press TAB when typing command name to auto-complete.

Your terminal application does not support escape sequences.

Line editing and history features are disabled.

On Windows, try using Putty instead.
cmd> I (982) bsp_display: SPI BUS init
I (983) bsp_display: Install panel IO
I (983) gpio: GPIO[42]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
W (1225) JD9853: The 3Ah command has been used and will be overwritten by external initialization sequence
I (1227) LVGL: Starting LVGL task
I (1311) bsp_display: LCD brightness set to 100%
I (1312) sdio_mount: try to mount sd card...
I (1313) gpio: GPIO[10]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1314) gpio: GPIO[11]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1315) gpio: GPIO[6]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1315) gpio: GPIO[7]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1316) gpio: GPIO[8]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1317) gpio: GPIO[9]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
E (1319) sdmmc_io: sdmmc_io_reset: unexpected return: 0x108
E (1319) vfs_fat_sdmmc: sdmmc_card_init failed (0x108).
I (1320) gpio: GPIO[10]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1320) gpio: GPIO[11]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1321) gpio: GPIO[6]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1322) gpio: GPIO[7]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1323) gpio: GPIO[8]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
I (1324) gpio: GPIO[9]| InputEn: 0| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0 
E (1324) sdio_mount: init sd card failed: ESP_ERR_INVALID_RESPONSE
E (1325) sdio_mount: Failed to create directory: /sdcard/fota: No such file or directory
E (1326) sdio_mount: Failed to create directory: /sdcard/sota: No such file or directory
E (1326) sdio_mount: Failed to create directory: /sdcard/sotabu: No such file or directory
I (1327) goer_ota: fota start signal create success
I (1328) goer_ota: sota start signal create success
I (1328) goer_ota: FOTA task start
I (1329) ota_interfaces: Registering OTA command
I (1330) transport: Attempt connection with slave: retry[0]
I (1330) spi: Reseting slave
I (1331) spi: Resetting slave on SPI bus with pin 44
I (1331) os_wrapper_esp: GPIO [44] configured
I (1331) gpio: GPIO[44]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (1834) transport: Waiting for esp_hosted slave to be ready
I (1921) transport: Received INIT event from ESP32 peripheral
I (1922) transport: EVENT: 12
I (1922) transport: Identified slave [esp32c5]
I (1922) transport: EVENT: 11
I (1923) transport: capabilities: 0xe8
I (1923) transport: Features supported are:
I (1923) transport: 	   - HCI over SPI
I (1924) transport: 	   - BLE only
I (1924) transport: EVENT: 13
W (1924) transport: === ESP-Hosted Version Warning ===
Version on Host is NEWER than version on co-processor
RPC requests sent by host may encounter timeout errors
or may not be supported by co-processor
W (1926) transport: === ESP-Hosted Version Warning ===
I (1926) transport: ESP board type is : 23 

I (1926) transport: Base transport is set-up, TRANSPORT_TX_ACTIVE
I (1927) H_API: Transport active
I (1927) transport: Slave chip Id[12]
I (1927) transport: raw_tp_dir[-], flow_ctrl: low[60] high[90]
I (1928) transport: transport_delayed_init
I (1928) esp_cli: Remove any existing deep_sleep cmd in cli
I (1929) esp_cli: Registering command: crash
I (1929) esp_cli: Registering command: reboot
I (1930) esp_cli: Registering command: mem-dump
I (1930) esp_cli: Registering command: task-dump
I (1930) esp_cli: Registering command: cpu-dump
I (1931) esp_cli: Registering command: heap-trace
I (1931) esp_cli: Registering command: sock-dump
I (1931) esp_cli: Registering command: host-power-save
I (1932) vhci_drv: Host BT Support: Enabled
I (1932) vhci_drv: 	BT Transport Type: VHCI
I (1933) spi: Received INIT event
I (2034) NimBLE_BLE_PRPH: BLE Host Task Started
connection_load_dataREAD connection INFO     0  0 
 I (2536) connection: NetWork not configed, start ble advertising 0  0 
<>connectivity_network_state_change 2 
I (2537) robot_master_main: Show <wakeup>
E (4035) NimBLE: HCI wait for ack returned 19 

I (4035) NimBLE: ogf=0x03, ocf=0x0003, core_err=0x13 : BLE_HS_ETIMEOUT_HCI (HCI request timed out; controller unresponsive)

E (4036) NimBLE: Resetting state; reason=19

E (6037) NimBLE: HCI wait for ack returned 19 

I (6037) NimBLE: ogf=0x03, ocf=0x0003, core_err=0x13 : BLE_HS_ETIMEOUT_HCI (HCI request timed out; controller unresponsive)

E (6038) NimBLE: Resetting state; reason=19

E (8038) NimBLE: HCI wait for ack returned 19 

I (8038) NimBLE: ogf=0x03, ocf=0x0003, core_err=0x13 : BLE_HS_ETIMEOUT_HCI (HCI request timed out; controller unresponsive)

E (8039) NimBLE: Resetting state; reason=19

E (10039) NimBLE: HCI wait for ack returned 19 

I (10039) NimBLE: ogf=0x03, ocf=0x0003, core_err=0x13 : BLE_HS_ETIMEOUT_HCI (HCI request timed out; controller unresponsive)

E (10040) NimBLE: Resetting state; reason=19

Steps to reproduce the behavior

1.idf.py create-project-from-example "espressif/esp_hosted=2.5.2:slave" change to spi communication config
2.esp32_p4 master using nimble for ble advertising

Project release version

slave 2.5.2-slave 2.6.1

System architecture

Intel/AMD 64-bit (modern PC, older Mac)

Operating system

Linux

Operating system version

ubuntu 22.04

Shell

ZSH

Additional context

No response

[MacChu0315-Espressif]

Dear esp-hosted-mcu Team, I have reminded our customer to use the latest unified version on both the host and the slave. However, the customer still encounters the HCI timeout issue even when both the host and the slave are running version v2.6.1. Could you please help look into this problem? The latest logs are as follows:
slavelog_v2.6.1.txt
hostlog_v2.6.1.txt

[mantriyogesh]

Hello @lisuchun6556 , @MacChu0315-Espressif ,

Please check the migration of bluetooh apis from 2.5.2:

Usage of Bluetooth APIs >= 2.5.2

Most likely this is the issue?

[lisuchun6556]

Thank for your answer.
The program is now working, but another HCI-TIMEOUT case was observed during testing:

Test case:

   ESP32-P4 host log level :info  +    ESP32-C5 slave log level :debug        SPI interface communication
   Master example: host_nimble_bleprph_host_only_vhci

If the ESP32-C5 log level is set to info, the program works properly.

Key error lines on the slave side:

W (7094) BLE_INIT: invalid controller state
E (7098) h_bt: esp_bt_controller_enable FAILED (or not called)
E (7104) slave_rpc: req_feature_control:3362 failed [enable_bluetooth()] = [-1]

------------Host log

ESP-ROM:esp32p4-eco2-20240710
Build:Jul 10 2024
rst:0x17 (CHIP_USB_UART_RESET),boot:0x30f (SPI_FAST_FLASH_BOOT)
Core0 Saved PC:0x4ff05d6c
--- 0x4ff05d6c: esp_cpu_wait_for_intr at /root/esp/v5.4.2/esp-idf/components/esp_hw_support/cpu.c:57
Core1 Saved PC:0x4ff05d6c
--- 0x4ff05d6c: esp_cpu_wait_for_intr at /root/esp/v5.4.2/esp-idf/components/esp_hw_support/cpu.c:57
SPI mode:DIO, clock div:1
load:0x4ff33ce0,len:0x15f0
load:0x4ff2abd0,len:0xd88
load:0x4ff2cbd0,len:0x3310
entry 0x4ff2abda
I (27) boot: ESP-IDF v5.4.2-dirty 2nd stage bootloader
I (28) boot: compile time Oct 21 2025 10:21:21
I (28) boot: Multicore bootloader
I (29) boot: chip revision: v1.0
I (31) boot: efuse block revision: v0.3
I (35) boot.esp32p4: SPI Speed : 80MHz
I (39) boot.esp32p4: SPI Mode : DIO
I (42) boot.esp32p4: SPI Flash Size : 2MB
I (46) boot: Enabling RNG early entropy source...
I (51) boot: Partition Table:
I (53) boot: ## Label Usage Type ST Offset Length
I (59) boot: 0 nvs WiFi data 01 02 00009000 00006000
I (66) boot: 1 phy_init RF data 01 01 0000f000 00001000
I (73) boot: 2 factory factory app 00 00 00010000 00100000
I (80) boot: End of partition table
I (82) esp_image: segment 0: paddr=00010020 vaddr=40080020 size=31b98h (203672) map
I (119) esp_image: segment 1: paddr=00041bc0 vaddr=30100000 size=00044h ( 68) load
I (120) esp_image: segment 2: paddr=00041c0c vaddr=4ff00000 size=0e40ch ( 58380) load
I (133) esp_image: segment 3: paddr=00050020 vaddr=40000020 size=76bbch (486332) map
I (202) esp_image: segment 4: paddr=000c6be4 vaddr=4ff0e40c size=04ac0h ( 19136) load
I (207) esp_image: segment 5: paddr=000cb6ac vaddr=4ff12f00 size=02744h ( 10052) load
I (214) boot: Loaded app from partition at offset 0x10000
I (214) boot: Disabling RNG early entropy source...
I (227) cpu_start: Multicore app
I (237) cpu_start: Pro cpu start user code
I (237) cpu_start: cpu freq: 360000000 Hz
I (237) app_init: Application information:
I (237) app_init: Project name: bleprph_host_only_vhci
I (242) app_init: App version: 1
I (245) app_init: Compile time: Oct 21 2025 10:21:18
I (250) app_init: ELF file SHA256: 4e439d720...
I (255) app_init: ESP-IDF: v5.4.2-dirty
I (259) efuse_init: Min chip rev: v0.1
I (263) efuse_init: Max chip rev: v1.99
I (267) efuse_init: Chip rev: v1.0
I (271) heap_init: Initializing. RAM available for dynamic allocation:
I (277) heap_init: At 4FF18F40 len 00022080 (136 KiB): RAM
I (282) heap_init: At 4FF3AFC0 len 00004BF0 (18 KiB): RAM
I (287) heap_init: At 4FF40000 len 00060000 (384 KiB): RAM
I (293) heap_init: At 50108080 len 00007F80 (31 KiB): RTCRAM
I (298) heap_init: At 30100044 len 00001FBC (7 KiB): TCM
I (304) spi_flash: detected chip: generic
W (307) spi_flash: Detected flash size > 16 MB, but access beyond 16 MB is not supported for this flash model yet.
I (317) spi_flash: flash io: dio
W (320) spi_flash: Detected size(32768k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (332) host_init: ESP Hosted : Host chip_ip[18]
I (336) H_API: ESP-Hosted starting. Hosted_Tasks: prio:23, stack: 5120 RPC_task_stack: 5120
I (345) H_API: ** add_esp_wifi_remote_channels **
I (349) transport: Add ESP-Hosted channel IF[1]: S[0] Tx[0x4000ee16] Rx[0x40021de2]
--- 0x4000ee16: transport_drv_sta_tx at /home/WorkFile/Project/test_c5/host_nimble_bleprph_host_only_vhci/managed_components/espressif__esp_hosted/host/drivers/transport/transport_drv.c:245
--- 0x40021de2: esp_wifi_remote_channel_rx at /home/WorkFile/Project/test_c5/host_nimble_bleprph_host_only_vhci/managed_components/espressif__esp_wifi_remote/esp_wifi_remote_net.c:19
I (356) transport: Add ESP-Hosted channel IF[2]: S[0] Tx[0x4000ed5a] Rx[0x40021de2]
--- 0x4000ed5a: transport_drv_ap_tx at /home/WorkFile/Project/test_c5/host_nimble_bleprph_host_only_vhci/managed_components/espressif__esp_hosted/host/drivers/transport/transport_drv.c:275
--- 0x40021de2: esp_wifi_remote_channel_rx at /home/WorkFile/Project/test_c5/host_nimble_bleprph_host_only_vhci/managed_components/espressif__esp_wifi_remote/esp_wifi_remote_net.c:19
spi_mempool_create free:169460 min-free:169460 lfb-def:126976 lfb-8bit:126976

I (371) spi_wrapper: Transport: SPI, Mode:3 Freq:40MHz TxQ:20 RxQ:20
GPIOs: CLK:18 MOSI:14 MISO:15 CS:19 HS:16 DR:17 SlaveReset:47
I (384) spi: Staring SPI task
I (385) os_wrapper_esp: GPIO [16] configuring as Interrupt
I (390) gpio: GPIO[16]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (399) main_task: Started on CPU0
I (399) os_wrapper_esp: GPIO [17] configuring as Interrupt
I (407) gpio: GPIO[17]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
I (416) main_task: Calling app_main()
I (423) H_API: ESP-Hosted Try to communicate with ESP-Hosted slave

I (425) transport: Attempt connection with slave: retry[0]
I (430) spi: Reseting slave
I (432) spi: Resetting slave on SPI bus with pin 47
I (437) os_wrapper_esp: GPIO [47] configured
I (441) gpio: GPIO[47]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
I (951) transport: Waiting for esp_hosted slave to be ready
I (1015) spi: rx packet ignored: len [65535], rcvd_offset[65535], exp_offset[12]

I (1488) transport: Received INIT event from ESP32 peripheral
I (1488) transport: EVENT: 12
I (1488) transport: Identified slave [esp32c5]
I (1489) transport: EVENT: 11
I (1492) transport: capabilities: 0xe8
I (1495) transport: Features supported are:
I (1499) transport: - HCI over SPI
I (1503) transport: - BLE only
I (1506) transport: EVENT: 13
I (1508) transport: ESP board type is : 23

I (1513) transport: Base transport is set-up, TRANSPORT_TX_ACTIVE
I (1519) H_API: Transport active
I (1521) transport: Slave chip Id[12]
I (1525) transport: raw_tp_dir[-], flow_ctrl: low[60] high[90]
I (1530) transport: transport_delayed_init
I (1534) esp_cli: Remove any existing deep_sleep cmd in cli
I (1540) esp_cli: Registering command: crash
I (1543) esp_cli: Registering command: reboot
I (1548) esp_cli: Registering command: mem-dump
I (1551) INFO: getting fw version
I (1552) esp_cli: Registering command: task-dump
I (1559) esp_cli: Registering command: cpu-dump
I (1563) esp_cli: Registering command: heap-trace
I (1568) esp_cli: Registering command: sock-dump
I (1572) esp_cli: Registering command: host-power-save
I (1577) vhci_drv: Host BT Support: Enabled
I (1581) vhci_drv: BT Transport Type: VHCI
I (1585) spi: Received INIT event
I (2489) INFO: FW Version: 2.6.1
W (7489) rpc_core: Timeout waiting for Resp for Req[0x183]
E (7489) rpc_core: Response not received for [0x183]
W (7489) INFO: failed to init bt controller
W (7612) rpc_rsp: Hosted RPC_Resp [0x283], uid [3], resp code [-1]
W (7613) INFO: failed to enable bt controller
I (7613) transport: Attempt connection with slave: retry[0]
I (7617) transport: Transport is already up
I (7621) NimBLE_BLE_PRPH: BLE Host Task Started
I (7628) uart: queue free spaces: 8
I (7629) main_task: Returned from app_main()
E (9628) NimBLE: HCI wait for ack returned 19

I (9628) NimBLE: ogf=0x03, ocf=0x0003, core_err=0x13 : BLE_HS_ETIMEOUT_HCI (HCI request timed out; controller unresponsive)

E (9632) NimBLE: Resetting state; reason=19

E (11636) NimBLE: HCI wait for ack returned 19

I (11636) NimBLE: ogf=0x03, ocf=0x0003, core_err=0x13 : BLE_HS_ETIMEOUT_HCI (HCI request timed out; controller unresponsive)

E (11640) NimBLE: Resetting state; reason=19

------------------------------slave log

D (29273) SPI_DRIVER: - reset handshake gpio
D (29273) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (29273) SPI_DRIVER: + set handshake gpio
D (29274) SPI_DRIVER: - reset handshake gpio
D (29274) SPI_DRIVER: spi_rx: buf_len[3], print_len[3]
D (29283) spi_rx: 0x4082959c 04 00 03 |...|
D (29291) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (29296) SPI_DRIVER: + set handshake gpio
D (29292) co-pro-main: bus_RX: buf_len[15], print_len[15]
D (29305) bus_RX: 0x4082959c 04 00 03 00 0c 00 00 00 00 00 00 01 03 0c 00 |...............|
I (30948) stats: STA: flw_ctrl(on[0] off[32]) H2S(in[0] out[0] fail[0]) S2H(in[0] out[0]) Ctrl: (in[2] rsp[2] evt[0])
I (30948) stats: Lwip: in[0] slave_out[0] host_out[0] both_out[0]
D (31281) SPI_DRIVER: - reset handshake gpio
D (31281) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (31281) SPI_DRIVER: + set handshake gpio
D (31282) SPI_DRIVER: - reset handshake gpio
D (31282) SPI_DRIVER: spi_rx: buf_len[3], print_len[3]
D (31291) spi_rx: 0x4082891c 04 00 03 |...|
D (31299) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (31304) SPI_DRIVER: + set handshake gpio
D (31300) co-pro-main: bus_RX: buf_len[15], print_len[15]
D (31313) bus_RX: 0x4082891c 04 00 03 00 0c 00 00 00 00 00 00 01 03 0c 00 |...............|
D (31563) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (31563) SPI_DRIVER: + set handshake gpio
D (31946) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (31947) SPI_DRIVER: + set handshake gpio
I (322) esp_image: segment 3: paddr=00139288 vaddr=408039f8 sizeng: tuning success, best point is index 4
I (409) MSPI Timing: Flash timing tuning index: 4
I (413) cpu_start: Unicore app
D (416) cpu_start: Pro cpu up
D (426) clk: RTC_SLOW_CLK calibration value: 3436181
D (446) cpu_start: calling init function: 0x4200029a on core: 0
D (447) cpu_start: calling init function: 0x42000a84 on core: 0
I (447) cpu_start: Pro cpu start user code
I (450) cpu_start: cpu freq: 240000000 Hz
D (454) cpu_start: calling init function: 0x42000120 on core: 0
I (460) app_init: Application information:
I (463) app_init: Project name: network_adapter
I (468) app_init: App version: 2.6.1
I (472) app_init: Compile time: Oct 21 2025 10:03:53
I (477) app_init: ELF file SHA256: 0dc72c70a...
I (481) app_init: ESP-IDF: v5.5.1-dirty
D (485) cpu_start: calling init function: 0x420002aa on core: 0
I (491) efuse_init: Min chip rev: v1.0
I (495) efuse_init: Max chip rev: v1.99
I (499) efuse_init: Chip rev: v1.0
D (503) cpu_start: calling init function: 0x420025cc on core: 0
D (508) memory_layout: Checking 5 reserved memory ranges:
D (513) memory_layout: Reserved memory range 0x40800000 - 0x40819300
D (519) memory_layout: Reserved memory range 0x40819300 - 0x40824960
D (526) memory_layout: Reserved memory range 0x4085f4f8 - 0x40860000
D (532) memory_layout: Reserved memory range 0x50000000 - 0x50000000
D (538) memory_layout: Reserved memory range 0x50003fe8 - 0x50004000
D (544) memory_layout: Building list of available memory regions:
D (550) memory_layout: Available memory region 0x40824960 - 0x4085c5a0
D (556) memory_layout: Available memory region 0x4085c5a0 - 0x4085f4f8
D (562) memory_layout: Available memory region 0x50000000 - 0x50003fe8
I (568) heap_init: Initializing. RAM available for dynamic allocation:
D (575) heap_init: New heap initialised at 0x40824960
I (579) heap_init: At 40824960 len 00037C40 (223 KiB): RAM
I (585) heap_init: At 4085C5A0 len 00002F58 (11 KiB): RAM
D (590) heap_init: New heap initialised at 0x50000000
I (594) heap_init: At 50000000 len 00003FE8 (15 KiB): RTCRAM
D (600) cpu_start: calling init function: 0x42000020 on core: 0
D (606) cpu_start: calling init function: 0x4200661c on core: 0
D (611) cpu_start: calling init function: 0x42000b16 on core: 0
D (617) intr_alloc: Connected src 15 to int 0 (cpu 0)
D (622) cpu_start: calling init function: 0x42000b38 on core: 0
D (627) cpu_start: calling init function: 0x42007ca4 on core: 0
D (633) cpu_start: calling init function: 0x42008fcc on core: 0
D (639) cpu_start: calling init function: 0x4200ac72 on core: 0
D (644) cpu_start: calling init function: 0x42009a56 on core: 0
D (650) cpu_start: calling init function: 0x4200662a on core: 0
D (656) cpu_start: calling init function: 0x42000bae on core: 0
D (661) spi_flash: trying chip: gd
D (664) spi_flash: trying chip: boya
D (667) spi_flash: trying chip: generic
I (671) spi_flash: detected chip: generic
I (675) spi_flash: flash io: qio
D (678) chip_generic: set_io_mode: status before 0x200
D (683) cpu_start: calling init function: 0x42000296 on core: 0
D (688) cpu_start: calling init function: 0x420baff8
D (693) cpu_start: calling init function: 0x4205de3c
D (698) cpu_start: calling init function: 0x4080d9be
D (702) cpu_start: calling init function: 0x4080e6e8
D (707) cpu_start: calling init function: 0x4080e6ac
D (712) cpu_start: calling init function: 0x42051616 on core: 0
D (717) intr_alloc: Connected src 63 to int 2 (cpu 0)
D (722) cpu_start: calling init function: 0x4200198e on core: 0
D (728) cpu_start: calling init function: 0x42056dd4 on core: 0
D (733) cpu_start: calling init function: 0x420029ba on core: 0
D (739) cpu_start: calling init function: 0x420037ec on core: 0
I (745) sleep_gpio: Configure to isolate all GPIO pins in sleep state
I (751) sleep_gpio: Enable automatic switching of GPIO sleep configuration
D (757) cpu_start: calling init function: 0x420d457c on core: 0
D (763) cpu_start: calling init function: 0x42000b48 on core: 0
I (769) coexist: coex firmware version: b0bcc39
I (773) coexist: coexist rom version 78e5c6e42
D (777) cpu_start: calling init function: 0x42000b60 on core: 0
D (783) cpu_start: calling init function: 0x42008b82 on core: 0
D (788) cpu_start: calling init function: 0x42000b78 on core: 0
D (794) intr_alloc: Connected src 23 to int 3 (cpu 0)
D (799) app_start: Starting scheduler on CPU0
D (803) intr_alloc: Connected src 61 to int 4 (cpu 0)
I (803) main_task: Started on CPU0
D (806) heap_init: New heap initialised at 0x4085c5a0
D (810) intr_alloc: Connected src 58 to int 5 (cpu 0)
I (815) main_task: Calling app_main()
I (825) co-pro-main: *********************************************************************
I (827) co-pro-main: ESP-Hosted-MCU Slave FW version :: 2.6.1
I (836) co-pro-main: Transport used :: SPI only
I (843) co-pro-main: *********************************************************************
I (851) SPI_DRIVER: Using SPI interface
D (867) gpio: GPIO[3]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
D (879) gpio: GPIO[4]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0
D (879) SPI_DRIVER: - reset handshake gpio
I (880) SPI_DRIVER: SPI Ctrl:1 mode: 3, Freq:ConfigAtHost
GPIOs: CLK:6 MOSI:7 MISO:2 CS:10 HS:3 DR:4

I (889) SPI_DRIVER: Hosted SPI queue size: Tx:20 Rx:20
D (894) gpio: GPIO[10]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:0
D (902) intr_alloc: Connected src 31 to int 7 (cpu 0)
D (907) gdma: new group (0) at 0x4085d668
D (911) gdma: new pair (0,0) at 0x4085d6e8
D (914) gdma: new tx channel (0,0) at 0x4085d630
D (919) gdma: new rx channel (0,0) at 0x4085d708
D (923) spi: SPI2 use iomux pins.
D (926) intr_alloc: Connected src 77 to int 8 (cpu 0)
I (931) SPI_DRIVER: SPI post process task started
D (935) event: running task for loop 0x4085e97c
D (940) event: created task for loop 0x4085e97c
D (944) event: created event loop 0x4085e97c
I (948) co-pro-main: Mandate host wakeup
I (951) co-pro-main: host reset handler task started
I (956) co-pro-main: Supported features are:
I (960) co-pro-main: - WLAN over SPI
I (963) h_bt: - BT/BLE
I (966) h_bt: - HCI Over SPI
I (968) h_bt: - BLE only
I (971) co-pro-main: capabilities: 0xe8
I (974) co-pro-main: Supported extended features are:
I (979) h_bt: - BT/BLE (extended)
I (982) co-pro-main: extended capabilities: 0x0
I (987) co-pro-main: host reconfig event
I (990) SPI_DRIVER: Slave chip Id[12]
D (994) SPI_DRIVER: + set dataready gpio
D (997) SPI_DRIVER: spi_tx: buf_len[36], print_len[32]
D (1002) spi_tx: 0x4082891c 05 00 17 00 0c 00 41 02 00 00 00 33 22 15 12 01 |......A....3"...|
D (1011) spi_tx: 0x4082892c 17 11 01 e8 13 01 00 14 01 14 15 01 14 17 04 01 |................|
D (1020) SPI_DRIVER: + set handshake gpio
D (1023) SPI_DRIVER: - reset handshake gpio
D (1027) SPI_DRIVER: - reset dataready gpio
I (1023) main_task: Returned from app_main()
D (1031) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (1040) SPI_DRIVER: + set handshake gpio
D (1066) SPI_DRIVER: - reset handshake gpio
D (1066) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (1067) SPI_DRIVER: + set handshake gpio
D (1067) SPI_DRIVER: - reset handshake gpio
D (1067) SPI_DRIVER: spi_rx: buf_len[17], print_len[17]
D (1076) spi_rx: 0x40829bdc 05 00 11 00 0c 00 00 00 00 00 00 00 22 0f 44 01 |............".D.|
D (1085) spi_rx: 0x40829bec 00 |.|
D (1092) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (1097) SPI_DRIVER: + set handshake gpio
D (1093) co-pro-main: bus_RX: buf_len[29], print_len[29]
D (1106) bus_RX: 0x40829bdc 05 00 11 00 0c 00 00 00 00 00 00 00 22 0f 44 01 |............".D.|
D (1115) bus_RX: 0x40829bec 00 45 01 17 46 01 00 47 01 5a 48 01 3c |.E..F..G.ZH.<|
I (1123) co-pro-main: Slave init_config received from host
D (1128) co-pro-main: init_config: buf_len[15], print_len[15]
D (1134) init_config: 0x40829bea 44 01 00 45 01 17 46 01 00 47 01 5a 48 01 3c |D..E..F..G.ZH.<|
D (1143) co-pro-main: Init event length: 15
I (1147) co-pro-main: Host capabilities: 44
I (1150) co-pro-main: ESP<-Host wifi flow ctl start thres [90%]
I (1156) co-pro-main: ESP<-Host wifi flow ctl clear thres [60%]
D (1920) SPI_DRIVER: - reset handshake gpio
D (1921) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (1921) SPI_DRIVER: + set handshake gpio
D (1921) SPI_DRIVER: - reset handshake gpio
D (1921) SPI_DRIVER: spi_rx: buf_len[20], print_len[20]
D (1930) spi_rx: 0x4082a21c 03 00 14 00 0c 00 00 00 00 00 00 00 01 06 00 52 |...............R|
D (1939) spi_rx: 0x4082a22c 50 43 52 73 |PCRs|
D (1947) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (1952) SPI_DRIVER: + set handshake gpio
D (1948) co-pro-main: bus_RX: buf_len[32], print_len[32]
D (1960) bus_RX: 0x4082a21c 03 00 14 00 0c 00 00 00 00 00 00 00 01 06 00 52 |...............R|
D (1969) bus_RX: 0x4082a22c 50 43 52 73 70 02 08 00 10 de 02 18 01 f2 15 00 |PCRsp...........|
I (1978) slave_rpc: Resp_MSGId for req[0x15e] is [0x25e], uid 1
I (1983) slave_rpc: Received Req [0x15e]
D (1987) protocomm: No encrypt ret 0
D (1990) SPI_DRIVER: + set dataready gpio
D (1994) SPI_DRIVER: - reset handshake gpio
D (1998) SPI_DRIVER: spi_tx: buf_len[40], print_len[32]
D (2003) spi_tx: 0x4082a21c 03 00 1c 00 0c 00 e2 04 01 00 00 00 01 06 00 52 |...............R|
D (2012) spi_tx: 0x4082a22c 50 43 52 73 70 02 10 00 08 02 10 de 04 18 01 f2 |PCRsp...........|
D (2020) SPI_DRIVER: + set handshake gpio
D (2024) SPI_DRIVER: - reset handshake gpio
D (2024) SPI_DRIVER: - reset handshake gpio
D (2032) SPI_DRIVER: - reset dataready gpio
D (2035) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (2040) SPI_DRIVER: + set handshake gpio
D (2044) SPI_DRIVER: - reset handshake gpio
D (2048) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (2053) SPI_DRIVER: + set handshake gpio
D (7027) SPI_DRIVER: - reset handshake gpio
D (7028) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (7028) SPI_DRIVER: + set handshake gpio
D (7028) SPI_DRIVER: - reset handshake gpio
D (7028) SPI_DRIVER: spi_rx: buf_len[24], print_len[24]
D (7037) spi_rx: 0x4082a21c 03 00 18 00 0c 00 00 00 00 00 00 00 01 06 00 52 |...............R|
D (7046) spi_rx: 0x4082a22c 50 43 52 73 70 02 0c 00 |PCRsp...|
D (7054) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (7059) SPI_DRIVER: + set handshake gpio
D (7055) co-pro-main: bus_RX: buf_len[36], print_len[32]
D (7068) bus_RX: 0x4082a21c 03 00 18 00 0c 00 00 00 00 00 00 00 01 06 00 52 |...............R|
D (7076) bus_RX: 0x4082a22c 50 43 52 73 70 02 0c 00 10 83 03 18 03 9a 18 04 |PCRsp...........|
I (7085) slave_rpc: Resp_MSGId for req[0x183] is [0x283], uid 3
I (7091) slave_rpc: Received Req [0x183]
W (7094) BLE_INIT: invalid controller state
E (7098) h_bt: esp_bt_controller_enable FAILED (or not called)
E (7104) slave_rpc: req_feature_control:3362 failed [enable_bluetooth()] = [-1]
D (7111) protocomm: No encrypt ret 0
D (7114) SPI_DRIVER: + set dataready gpio
D (7118) SPI_DRIVER: - reset handshake gpio
D (7122) SPI_DRIVER: spi_tx: buf_len[52], print_len[32]
D (7127) spi_tx: 0x4082a21c 03 00 25 00 0c 00 2c 0d 02 00 00 00 01 06 00 52 |..%...,........R|
D (7135) spi_tx: 0x4082a22c 50 43 52 73 70 02 19 00 08 02 10 83 05 18 03 9a |PCRsp...........|
D (7144) SPI_DRIVER: + set handshake gpio
D (7148) SPI_DRIVER: - reset handshake gpio
D (7151) SPI_DRIVER: - reset dataready gpio
D (7155) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (7160) SPI_DRIVER: + set handshake gpio
D (7164) SPI_DRIVER: - reset handshake gpio
D (7168) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (7173) SPI_DRIVER: + set handshake gpio
D (7176) SPI_DRIVER: spi_rx: buf_len[3], print_len[3]
D (7181) spi_rx: 0x4082891c 04 00 03 |...|
D (7189) co-pro-main: bus_RX: buf_len[15], print_len[15]
D (7194) bus_RX: 0x4082891c 04 00 03 00 0c 00 00 00 00 00 00 01 03 0c 00 |...............|
D (9172) SPI_DRIVER: - reset handshake gpio
D (9172) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (9172) SPI_DRIVER: + set handshake gpio
D (9173) SPI_DRIVER: - reset handshake gpio
D (9173) SPI_DRIVER: spi_rx: buf_len[3], print_len[3]
D (9182) spi_rx: 0x4082a21c 04 00 03 |...|
D (9189) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (9194) SPI_DRIVER: + set handshake gpio
D (9190) co-pro-main: bus_RX: buf_len[15], print_len[15]
D (9203) bus_RX: 0x4082a21c 04 00 03 00 0c 00 00 00 00 00 00 01 03 0c 00 |...............|
D (11180) SPI_DRIVER: - reset handshake gpio
D (11180) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (11180) SPI_DRIVER: + set handshake gpio
D (11182) SPI_DRIVER: - reset handshake gpio
D (11181) SPI_DRIVER: spi_rx: buf_len[3], print_len[3]
D (11190) spi_rx: 0x4082959c 04 00 03 |...|
D (11198) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (11203) SPI_DRIVER: + set handshake gpio
D (11199) co-pro-main: bus_RX: buf_len[15], print_len[15]
D (11212) bus_RX: 0x4082959c 04 00 03 00 0c 00 00 00 00 00 00 01 03 0c 00 |...............|
D (13188) SPI_DRIVER: - reset handshake gpio
D (13188) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (13189) SPI_DRIVER: + set handshake gpio
D (13190) SPI_DRIVER: - reset handshake gpio
D (13190) SPI_DRIVER: spi_rx: buf_len[3], print_len[3]
D (13199) spi_rx: 0x4082891c 04 00 03 |...|
D (13206) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (13211) SPI_DRIVER: + set handshake gpio
D (13207) co-pro-main: bus_RX: buf_len[15], print_len[15]
D (13220) bus_RX: 0x4082891c 04 00 03 00 0c 00 00 00 00 00 00 01 03 0c 00 |...............|
D (15242) SPI_DRIVER: - reset handshake gpio
D (15242) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (15242) SPI_DRIVER: + set handshake gpio
D (15243) SPI_DRIVER: - reset handshake gpio
D (15243) SPI_DRIVER: spi_rx: buf_len[3], print_len[3]
D (15252) spi_rx: 0x4082a21c 04 00 03 |...|
D (15260) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (15265) SPI_DRIVER: + set handshake gpio
D (15261) co-pro-main: bus_RX: buf_len[15], print_len[15]
D (15274) bus_RX: 0x4082a21c 04 00 03 00 0c 00 00 00 00 00 00 01 03 0c 00 |...............|
D (17250) SPI_DRIVER: - reset handshake gpio
D (17250) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (17251) SPI_DRIVER: + set handshake gpio
D (17252) SPI_DRIVER: - reset handshake gpio
D (17252) SPI_DRIVER: spi_rx: buf_len[3], print_len[3]
D (17261) spi_rx: 0x4082959c 04 00 03 |...|
D (17268) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (17273) SPI_DRIVER: + set handshake gpio
D (17269) co-pro-main: bus_RX: buf_len[15], print_len[15]
D (17282) bus_RX: 0x4082959c 04 00 03 00 0c 00 00 00 00 00 00 01 03 0c 00 |...............|
D (19258) SPI_DRIVER: - reset handshake gpio
D (19259) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (19259) SPI_DRIVER: + set handshake gpio
D (19260) SPI_DRIVER: - reset handshake gpio
D (19260) SPI_DRIVER: spi_rx: buf_len[3], print_len[3]
D (19269) spi_rx: 0x4082891c 04 00 03 |...|
D (19276) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (19281) SPI_DRIVER: + set handshake gpio
D (19277) co-pro-main: bus_RX: buf_len[15], print_len[15]
D (19290) bus_RX: 0x4082891c 04 00 03 00 0c 00 00 00 00 00 00 01 03 0c 00 |...............|
D (21266) SPI_DRIVER: - reset handshake gpio
D (21267) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (21267) SPI_DRIVER: + set handshake gpio
D (21268) SPI_DRIVER: - reset handshake gpio
D (21268) SPI_DRIVER: spi_rx: buf_len[3], print_len[3]
D (21277) spi_rx: 0x4082a21c 04 00 03 |...|
D (21284) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (21289) SPI_DRIVER: + set handshake gpio
D (21285) co-pro-main: bus_RX: buf_len[15], print_len[15]
D (21298) bus_RX: 0x4082a21c 04 00 03 00 0c 00 00 00 00 00 00 01 03 0c 00 |...............|
D (23274) SPI_DRIVER: - reset handshake gpio
D (23275) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (23275) SPI_DRIVER: + set handshake gpio
D (23276) SPI_DRIVER: - reset handshake gpio
D (23276) SPI_DRIVER: spi_rx: buf_len[3], print_len[3]
D (23285) spi_rx: 0x4082959c 04 00 03 |...|
D (23293) co-pro-main: bus_RX: buf_len[15], print_len[15]
D (23294) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (23302) SPI_DRIVER: + set handshake gpio
D (23299) bus_RX: 0x4082959c 04 00 03 00 0c 00 00 00 00 00 00 01 03 0c 00 |...............|
D (25282) SPI_DRIVER: - reset handshake gpio
D (25283) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (25283) SPI_DRIVER: + set handshake gpio
D (25284) SPI_DRIVER: - reset handshake gpio
D (25284) SPI_DRIVER: spi_rx: buf_len[3], print_len[3]
D (25293) spi_rx: 0x4082891c 04 00 03 |...|
D (25301) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (25305) SPI_DRIVER: + set handshake gpio
D (25302) co-pro-main: bus_RX: buf_len[15], print_len[15]
D (25314) bus_RX: 0x4082891c 04 00 03 00 0c 00 00 00 00 00 00 01 03 0c 00 |...............|
D (27290) SPI_DRIVER: - reset handshake gpio
D (27291) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (27291) SPI_DRIVER: + set handshake gpio
D (27292) SPI_DRIVER: - reset handshake gpio
D (27292) SPI_DRIVER: spi_rx: buf_len[3], print_len[3]
D (27301) spi_rx: 0x4082a21c 04 00 03 |...|
D (27309) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (27313) SPI_DRIVER: + set handshake gpio
D (27310) co-pro-main: bus_RX: buf_len[15], print_len[15]
D (27322) bus_RX: 0x4082a21c 04 00 03 00 0c 00 00 00 00 00 00 01 03 0c 00 |...............|
D (29298) SPI_DRIVER: - reset handshake gpio
D (29299) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (29299) SPI_DRIVER: + set handshake gpio
D (29300) SPI_DRIVER: - reset handshake gpio
D (29300) SPI_DRIVER: spi_rx: buf_len[3], print_len[3]
D (29309) spi_rx: 0x4082959c 04 00 03 |...|
D (29317) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (29321) SPI_DRIVER: + set handshake gpio
D (29318) co-pro-main: bus_RX: buf_len[15], print_len[15]
D (29330) bus_RX: 0x4082959c 04 00 03 00 0c 00 00 00 00 00 00 01 03 0c 00 |...............|
I (30948) stats: STA: flw_ctrl(on[0] off[32]) H2S(in[0] out[0] fail[0]) S2H(in[0] out[0]) Ctrl: (in[2] rsp[2] evt[0])
I (30948) stats: Lwip: in[0] slave_out[0] host_out[0] both_out[0]
D (31306) SPI_DRIVER: - reset handshake gpio
D (31307) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (31307) SPI_DRIVER: + set handshake gpio
D (31308) SPI_DRIVER: - reset handshake gpio
D (31308) SPI_DRIVER: spi_rx: buf_len[3], print_len[3]
D (31317) spi_rx: 0x4082891c 04 00 03 |...|
D (31325) SPI_DRIVER: spi_tx: buf_len[0], print_len[0]
D (31329) SPI_DRIVER: + set handshake gpio
D (31326) co-pro-main: bus_RX: buf_len[15], print_len[15]
D (31338) bus_RX: 0x4082891c 04 00 03 00 0c 00 00 00 00 00 00 01 03 0c 00 |...............|

[SohKamYung-Espressif]

Hello, @lisuchun6556

In the Host Log in #115 (comment) I see this:

I (1581) vhci_drv: BT Transport Type: VHCI
I (1585) spi: Received INIT event
I (2489) INFO: FW Version: 2.6.1
W (7489) rpc_core: Timeout waiting for Resp for Req[0x183]
E (7489) rpc_core: Response not received for [0x183]
W (7489) INFO: failed to init bt controller
W (7612) rpc_rsp: Hosted RPC_Resp [0x283], uid [3], resp code [-1]
W (7613) INFO: failed to enable bt controller

The timeout usually indicates a transport error.

How are you connecting the ESP32-P4 to the ESP32-C5? Are you using a PCB or wires? If you are using wires, try lowering the SPI CLK from 40 MHz to a lower value (maybe 20 MHz), and see if helps. Also, keep the wires as short as possible.

FYI, I just tested the Test Case host_nimble_bleprph_host_only_vhci example on a P4 connected to a C5 via PCB, and the code works as expected. Here is a partial host log:

[...]
I (1150) vhci_drv: Host BT Support: Enabled
I (1154) vhci_drv:      BT Transport Type: VHCI
I (1158) spi: Received INIT event
I (1165) INFO: getting fw version
I (1427) INFO: FW Version: 2.6.1
I (2041) transport: Attempt connection with slave: retry[0]
I (2042) transport: Transport is already up
I (2042) NimBLE_BLE_PRPH: BLE Host Task Started
I (2045) uart: queue free spaces: 8
I (2045) main_task: Returned from app_main()
I (2062) NimBLE: GAP procedure initiated: stop advertising.

I (2067) NimBLE: Device Address:
I (2067) NimBLE: 30:ed:a0:e0:a9:de
I (2067) NimBLE:

I (2070) NimBLE: GAP procedure initiated: advertise;
I (2070) NimBLE: disc_mode=2
I (2072) NimBLE:  adv_channel_map=0 own_addr_type=0 adv_filter_policy=0 adv_itvl_min=0 adv_itvl_max=0
[...]