No Bluetooth SPP connection possible with IDF 4.3.2 (IDFGH-6766)

[euphi]

Environment

• Development Kit: [ESP32-Devkit-V1]

• Module or chip used: ESP32-WROOM-32|

• IDF version: 4.3.2 (version.txt)

• Build System: platformio

• Compiler version xtensa-esp32-elf-gcc (crosstool-NG esp-2021r2) 8.4.0

• Operating System: Linux

• Using an IDE?: not relevant

• Power Supply: USB

platformio

Platformio Configuration (platformio.ini):

[platformio]
src_dir = main

[env:esp32dev]
platform = espressif32
framework = espidf
board = esp32doit-devkit-v1

Platformio Environment:

CONFIGURATION: https://docs.platformio.org/page/boards/espressif32/esp32doit-devkit-v1.html
PLATFORM: Espressif 32 (3.5.0) > DOIT ESP32 DEVKIT V1
HARDWARE: ESP32 240MHz, 320KB RAM, 4MB Flash
DEBUG: Current (esp-prog) External (esp-prog, iot-bus-jtag, jlink, minimodule, olimex-arm-usb-ocd, olimex-arm-usb-ocd-h, olimex-arm-usb-tiny-h, olimex-jtag-tiny, tumpa)
PACKAGES: 
 - framework-espidf 3.40302.0 (4.3.2) 
 - tool-cmake 3.16.4 
 - tool-esptoolpy 1.30100.210531 (3.1.0) 
 - tool-mkspiffs 2.230.0 (2.30) 
 - tool-ninja 1.7.1 
 - toolchain-esp32ulp 1.22851.191205 (2.28.51) 
 - toolchain-riscv32-esp 8.4.0+2021r2-patch2 
 - toolchain-xtensa-esp32 8.4.0+2021r2-patch2 
 - toolchain-xtensa-esp32s2 8.4.0+2021r2-patch2

Problem Description

The "initiator" example can't connect to classic Bluetooth device.

There is already an issue for Arduino ESP32: espressif/arduino-esp32#6061

To investigate for that issue and exclude the IDF as root cause, I installed the IDF and tried the Initiator example.

It seems that the IDF has the same issue, as I can't connect to the device with the SPP Initiator example.

To rule out name resolving issue, I changed the code that it connect to a pre-configured adress, and then it is still not possible to complete connection.

I also asked a question at https://esp32.com/viewtopic.php?f=19&t=26042 - but there is no answer yet.

The log shows that a connection is initiated but then no serial connection is possible;

W (36287) BT_RFCOMM: port_rfc_closed RFCOMM connection in state 1 closed: Peer connection failed (res: 16)

Detailed Log:

32mI (3217) BT_BTM: BTM_InqDbRead: bd addr [201301180226]
 
D (3227) BT_BTM: btm_acl_paging discing:0, paging:0 BDA: 201301180226
0m
D (3227) BT_BTM: connecting_bda: 000000000000
 
D (3237) BT_BTM: btm_find_or_alloc_dev
 
D (3237) BT_BTM: btm_acl_update_busy_level
m
D (3247) BT_BTM: BTM_BLI_PAGE_EVT
 
0;32mI (3247) SPP_INITIATOR_DEMO: ESP_BT_GAP_DISC_STATE_CHANGED_EVT0m
D (5797) BT_BTM: btm_acl_resubmit_page
[0m
D (5797) BT_BTM: btm_acl_created hci_handle=129 link_role=1  transport=1
[0m
D (5797) BT_BTM: btm_read_remote_features() handle: 129
 
D (5797) BT_BTM: btm_handle_to_acl_index: 129
[0m
D (5807) BT_BTM: is_originator:0
 
D (5807) BT_BTM: btm_sec_execute_procedure: Required:0x0 Flags:0x4090 State:0
[0m
D (5817) BT_BTM: Security Manager: Start get name
[0m
D (5817) BT_BTM: btm_acl_paging discing:0, paging:0 BDA: 201301180226
 
D (5827) BT_BTM: btm_acl_update_busy_level
[0m
D (5827) BT_BTM: BTM_BLI_PAGE_DONE_EVT
[0m
D (5837) BT_BTM: btm_acl_created hci_handle=129 link_role=0  transport=1
0m
D (5847) BT_BTM: Duplicate btm_acl_created: RemBdAddr: 201301180226
 
D (5847) BT_BTM: BTM_SetLinkPolicy
[0m
D (5857) BT_BTM: BTM_SetLinkSuperTout
[0m
D (5857) BT_BTM: btm_sec_l2cap_access_req() is_originator:1, 0x3ffbb9d8
m
D (5867) BT_BTM: btm_find_or_alloc_dev
m
D (5867) BT_BTM: btm_sec_is_serv_level0: PSM: 0x0001 -> mode 4 level 0 service
 
D (5877) BT_BTM: btm_read_remote_version_complete
 
D (5877) BT_BTM: btm_handle_to_acl_index: 129
m
D (5887) BT_BTM: btm_read_remote_features_complete
0m
D (5887) BT_BTM: btm_handle_to_acl_index: 129
 
D (5897) BT_BTM: Start reading remote extended features
[0m
D (5897) BT_BTM: btm_read_remote_ext_features() handle: 129 page: 1
 
D (5907) BT_BTM: btm_process_clk_off_comp_evt
[0m
D (5907) BT_BTM: btm_handle_to_acl_index: 129
 
I (5917) BT_BTM: BTM_InqDbRead: bd addr [201301180226]
 
D (5927) BT_BTM: BDA 20:13:01:18:02:26
 
D (5927) BT_BTM: Inquire BDA 00:00:00:00:00:00
 
D (5927) BT_BTM: btm_sec_rmt_name_request_complete
 
D (5937) BT_BTM: setting BTM_SEC_NAME_KNOWN sec_flags:0x4098
 
D (5937) BT_BTM: btm_sec_execute_procedure: Required:0x0 Flags:0x4098 State:0
 
D (5947) BT_BTM: Security Manager: trusted:0x00000000
[0m
D (5957) BT_BTM: Security Manager: access granted
0m
D (5997) BT_BTM: btm_get_max_packet_size
[0m
[0;32mI (6067) BT_BTM: BTM_SetPowerMode: pm_id 128 BDA: 01180226 mode:0x0[0m
D (6067) BT_BTM: BTM_SetPowerMode: mode:0x0 interval 0 max:0, min:0
[0;32mI (6097) SPP_INITIATOR_DEMO: ESP_SPP_DISCOVERY_COMP_EVT scn_num:1
;32mI (6097) SPP_INITIATOR_DEMO: -- [0] scn:1 service_name:Dev B
I (6097) BT_BTM: btm_sec_set_security_level : sec: 0x12
 
I (6107) BT_BTM: BTM_SEC_REG[2]: id 52, is_orig 1, psm 0x0003, proto_id 3, chan_id 1
 
;32mI (6117) BT_BTM:                : sec: 0x2090, service name [] (up to 21 chars saved)
[0m
D (6127) BT_RFCOMM: port_find_mcb: not found, bd_addr:20:13:01:18:02:26
I (6127) BT_RFCOMM: RFCOMM_CreateConnection()  BDA: 20-13-01-18-02-26m
I (6137) BT_RFCOMM: RFCOMM_CreateConnection(): scn:1, dlci:2, is_server:0 mtu:990, p_mcb:0x00m
D (6147) BT_RFCOMM: rfc_cb.port.port[1]:0x3ffc33d8 allocated, last_port:1
D (6157) BT_RFCOMM: port_allocate_port:bd_addr:20:13:01:18:02:26m
I (6157) BT_RFCOMM: RFCOMM_CreateConnection(): scn:1, dlci:2, is_server:0 mtu:990, p_mcb:0x0, p_port:0x3ffc33d8
D (6167) BT_RFCOMM: RFCOMM_CreateConnection dlci:2 signal state:0xb0m
D (6177) BT_RFCOMM: port_open_continue, p_port:0x3ffc33d8
D (6187) BT_RFCOMM: rfc_alloc_multiplexer_channel: bd_addr:20:13:01:18:02:26
D (6187) BT_RFCOMM: rfc_alloc_multiplexer_channel:is_initiator:1
D (6197) BT_RFCOMM: rfc_alloc_multiplexer_channel rfc_cb.port.rfc_mcb[0].state:0[0m
D (6207) BT_RFCOMM: (rfc_cb.port.rfc_mcb[i].bd_addr:00:00:00:00:00:00
D (6207) BT_RFCOMM: rfc_alloc_multiplexer_channel rfc_cb.port.rfc_mcb[1].state:0[0m
D (6217) BT_RFCOMM: (rfc_cb.port.rfc_mcb[i].bd_addr:00:00:00:00:00:00
D (6227) BT_RFCOMM: rfc_alloc_multiplexer_channel rfc_cb.port.rfc_mcb[2].state:0[0m
D (6227) BT_RFCOMM: (rfc_cb.port.rfc_mcb[i].bd_addr:00:00:00:00:00:00
D (6237) BT_RFCOMM: rfc_alloc_multiplexer_channel rfc_cb.port.rfc_mcb[3].state:0[0m
D (6247) BT_RFCOMM: (rfc_cb.port.rfc_mcb[i].bd_addr:00:00:00:00:00:00
D (6247) BT_RFCOMM: rfc_timer_free[0m
D (6257) BT_RFCOMM: rfc_alloc_multiplexer_channel:is_initiator:1, create new p_mcb:0x3ffc3854, index:0
D (6267) BT_RFCOMM: rfc_timer_start - timeout:60[0m
D (6267) BT_RFCOMM: port_select_mtu application selected 990
D (6277) BT_RFCOMM: port_select_mtu credit_rx_max 10, credit_rx_low 4, rx_buf_critical 15[0m
D (6287) BT_RFCOMM: rfc_mx_sm_state_idle - evt:6
I (6287) BT_BTM: BTM_SetPowerMode: pm_id 128 BDA: 01180226 mode:0x0
D (6297) BT_BTM: BTM_SetPowerMode: mode:0x0 interval 0 max:0, min:0[0m
D (6297) BT_BTM: btm_sec_l2cap_access_req() is_originator:1, 0x3ffbb9d8
m
D (6307) BT_BTM: btm_find_or_alloc_dev
m
D (6317) BT_BTM: btm_sec_l2cap_access_req: security_required 0x2090, is_originator 0x01, psm  0x0003
 
31mE (6317) BT_BTM: btm_sec_l2cap_access_req: (initiator) remote features unknown!!sec_flags:0x4098
m
I (6327) BT_RFCOMM: PORT_SetEventCallback() handle:2
[0;32mI (6337) BT_RFCOMM: PORT_SetEventMask() handle:2 mask:0x300050m
I (6347) BT_RFCOMM: PORT_GetState() handle:2m
I (6347) BT_RFCOMM: PORT_SetState() handle:2m
I (6357) BT_RFCOMM: PORT_SetState() handle:2 FC_TYPE:0xcm
I (6357) SPP_INITIATOR_DEMO: ESP_SPP_CL_INIT_EVT handle:129 sec_id:520m
D (36277) BT_RFCOMM: rfc_mx_sm_state_wait_conn_cnf - evt:14
D (36277) BT_RFCOMM: PORT_CloseInd
D (36277) BT_RFCOMM: port_rfc_closed state:1 sending events:0
0;32mI (36277) BT_RFCOMM: PORT_CheckConnection() handle:2[0m
mW (36287) BT_RFCOMM: port_rfc_closed RFCOMM connection in state 1 closed: Peer connection failed (res: 16)
D (36297) BT_RFCOMM: port_release_port, p_port:0x3ffc33d8m
D (36307) BT_RFCOMM: rfc_port_closed DONE[0m
D (36307) BT_RFCOMM: rfc_timer_start - timeout:2
D (36307) BT_RFCOMM: rfc_port_timer_stop
D (36317) BT_RFCOMM: port_release_port:p_port->keep_port_handle:0m
D (36317) BT_RFCOMM: port_release_port:Clean-up handle:2
D (36327) BT_RFCOMM: rfc_port_timer_stop
D (36327) BT_RFCOMM: rfc_timer_free
D (36337) BT_BTM: btm_acl_removed
 
D (36337) BT_BTM: btm_acl_report_role_change
m
D (36347) BT_BTM: btm_acl_resubmit_page
0m
D (36347) BT_BTM: btm_sec_disconnected before update sec_flags=0x4098
 
D (36357) BT_BTM: btm_sec_disconnected after update sec_flags=0x98
[0m
I (36357) SPP_INITIATOR_DEMO: ESP_SPP_CLOSE_EVT status:0 handle:129 close_by_remote:1
[0;31mE (36367) BT_BTC: btc_spp_cb_handler unable to find RFCOMM slot!

SDK Config (bluetooth part only):

#
# Bluetooth
#
CONFIG_BT_ENABLED=y
CONFIG_BT_CTRL_ESP32=y

#
# Bluetooth controller(ESP32 Dual Mode Bluetooth)
#
# CONFIG_BTDM_CTRL_MODE_BLE_ONLY is not set
CONFIG_BTDM_CTRL_MODE_BR_EDR_ONLY=y
# CONFIG_BTDM_CTRL_MODE_BTDM is not set
CONFIG_BTDM_CTRL_BR_EDR_MAX_ACL_CONN=2
CONFIG_BTDM_CTRL_BR_EDR_MAX_SYNC_CONN=0
# CONFIG_BTDM_CTRL_BR_EDR_SCO_DATA_PATH_HCI is not set
CONFIG_BTDM_CTRL_BR_EDR_SCO_DATA_PATH_PCM=y
CONFIG_BTDM_CTRL_BR_EDR_SCO_DATA_PATH_EFF=1
CONFIG_BTDM_CTRL_PCM_ROLE_EDGE_CONFIG=y
CONFIG_BTDM_CTRL_PCM_ROLE_MASTER=y
# CONFIG_BTDM_CTRL_PCM_ROLE_SLAVE is not set
CONFIG_BTDM_CTRL_PCM_POLAR_FALLING_EDGE=y
# CONFIG_BTDM_CTRL_PCM_POLAR_RISING_EDGE is not set
CONFIG_BTDM_CTRL_PCM_ROLE_EFF=0
CONFIG_BTDM_CTRL_PCM_POLAR_EFF=0
CONFIG_BTDM_CTRL_LEGACY_AUTH_VENDOR_EVT=y
CONFIG_BTDM_CTRL_LEGACY_AUTH_VENDOR_EVT_EFF=y
CONFIG_BTDM_CTRL_BLE_MAX_CONN_EFF=0
CONFIG_BTDM_CTRL_BR_EDR_MAX_ACL_CONN_EFF=2
CONFIG_BTDM_CTRL_BR_EDR_MAX_SYNC_CONN_EFF=0
CONFIG_BTDM_CTRL_PINNED_TO_CORE_0=y
# CONFIG_BTDM_CTRL_PINNED_TO_CORE_1 is not set
CONFIG_BTDM_CTRL_PINNED_TO_CORE=0
CONFIG_BTDM_CTRL_HCI_MODE_VHCI=y
# CONFIG_BTDM_CTRL_HCI_MODE_UART_H4 is not set

#
# MODEM SLEEP Options
#
CONFIG_BTDM_CTRL_MODEM_SLEEP=y
CONFIG_BTDM_CTRL_MODEM_SLEEP_MODE_ORIG=y
# CONFIG_BTDM_CTRL_MODEM_SLEEP_MODE_EVED is not set
CONFIG_BTDM_CTRL_LPCLK_SEL_MAIN_XTAL=y
# end of MODEM SLEEP Options

CONFIG_BTDM_BLE_SLEEP_CLOCK_ACCURACY_INDEX_EFF=1
# end of Bluetooth controller(ESP32 Dual Mode Bluetooth)

CONFIG_BT_CTRL_MODE_EFF=1
CONFIG_BT_CTRL_BLE_MAX_ACT=10
CONFIG_BT_CTRL_BLE_MAX_ACT_EFF=10
CONFIG_BT_CTRL_BLE_STATIC_ACL_TX_BUF_NB=0
CONFIG_BT_CTRL_PINNED_TO_CORE=0
CONFIG_BT_CTRL_HCI_TL=1
CONFIG_BT_CTRL_ADV_DUP_FILT_MAX=30
CONFIG_BT_CTRL_HW_CCA_EFF=0
CONFIG_BT_CTRL_DFT_TX_POWER_LEVEL_EFF=0
CONFIG_BT_CTRL_BLE_ADV_REPORT_FLOW_CTRL_SUPP=y
CONFIG_BT_CTRL_BLE_ADV_REPORT_FLOW_CTRL_NUM=100
CONFIG_BT_CTRL_BLE_ADV_REPORT_DISCARD_THRSHOLD=20
CONFIG_BT_CTRL_BLE_SCAN_DUPL=y
CONFIG_BT_CTRL_SCAN_DUPL_TYPE=0
CONFIG_BT_CTRL_SCAN_DUPL_CACHE_SIZE=100
CONFIG_BT_CTRL_COEX_PHY_CODED_TX_RX_TLIM_EFF=0

#
# MODEM SLEEP Options
#
# end of MODEM SLEEP Options

CONFIG_BT_CTRL_SLEEP_MODE_EFF=0
CONFIG_BT_CTRL_SLEEP_CLOCK_EFF=0
CONFIG_BT_CTRL_HCI_TL_EFF=1

#
# MODEM SLEEP Options
#
# end of MODEM SLEEP Options

CONFIG_BT_BLUEDROID_ENABLED=y
# CONFIG_BT_NIMBLE_ENABLED is not set
# CONFIG_BT_CONTROLLER_ONLY is not set

#
# Bluedroid Options
#
CONFIG_BT_BTC_TASK_STACK_SIZE=3072
CONFIG_BT_BLUEDROID_PINNED_TO_CORE_0=y
# CONFIG_BT_BLUEDROID_PINNED_TO_CORE_1 is not set
CONFIG_BT_BLUEDROID_PINNED_TO_CORE=0
CONFIG_BT_BTU_TASK_STACK_SIZE=4096
# CONFIG_BT_BLUEDROID_MEM_DEBUG is not set
CONFIG_BT_CLASSIC_ENABLED=y
# CONFIG_BT_A2DP_ENABLE is not set
CONFIG_BT_SPP_ENABLED=y
# CONFIG_BT_HFP_ENABLE is not set
# CONFIG_BT_HID_HOST_ENABLED is not set
# CONFIG_BT_SSP_ENABLED is not set
# CONFIG_BT_BLE_ENABLED is not set
# CONFIG_BT_STACK_NO_LOG is not set

#
# BT DEBUG LOG LEVEL
#
# CONFIG_BT_LOG_HCI_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_HCI_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_HCI_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_HCI_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_HCI_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_HCI_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_HCI_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_HCI_TRACE_LEVEL=2
# CONFIG_BT_LOG_BTM_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_BTM_TRACE_LEVEL_ERROR is not set
# CONFIG_BT_LOG_BTM_TRACE_LEVEL_WARNING is not set
# CONFIG_BT_LOG_BTM_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_BTM_TRACE_LEVEL_EVENT is not set
CONFIG_BT_LOG_BTM_TRACE_LEVEL_DEBUG=y
# CONFIG_BT_LOG_BTM_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_BTM_TRACE_LEVEL=5
# CONFIG_BT_LOG_L2CAP_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_L2CAP_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_L2CAP_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_L2CAP_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_L2CAP_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_L2CAP_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_L2CAP_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_L2CAP_TRACE_LEVEL=2
# CONFIG_BT_LOG_RFCOMM_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_RFCOMM_TRACE_LEVEL_ERROR is not set
# CONFIG_BT_LOG_RFCOMM_TRACE_LEVEL_WARNING is not set
# CONFIG_BT_LOG_RFCOMM_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_RFCOMM_TRACE_LEVEL_EVENT is not set
CONFIG_BT_LOG_RFCOMM_TRACE_LEVEL_DEBUG=y
# CONFIG_BT_LOG_RFCOMM_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_RFCOMM_TRACE_LEVEL=5
# CONFIG_BT_LOG_SDP_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_SDP_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_SDP_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_SDP_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_SDP_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_SDP_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_SDP_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_SDP_TRACE_LEVEL=2
# CONFIG_BT_LOG_GAP_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_GAP_TRACE_LEVEL_ERROR is not set
# CONFIG_BT_LOG_GAP_TRACE_LEVEL_WARNING is not set
# CONFIG_BT_LOG_GAP_TRACE_LEVEL_API is not set
CONFIG_BT_LOG_GAP_TRACE_LEVEL_EVENT=y
# CONFIG_BT_LOG_GAP_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_GAP_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_GAP_TRACE_LEVEL=4
# CONFIG_BT_LOG_BNEP_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_BNEP_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_BNEP_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_BNEP_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_BNEP_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_BNEP_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_BNEP_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_BNEP_TRACE_LEVEL=2
# CONFIG_BT_LOG_PAN_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_PAN_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_PAN_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_PAN_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_PAN_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_PAN_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_PAN_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_PAN_TRACE_LEVEL=2
# CONFIG_BT_LOG_A2D_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_A2D_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_A2D_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_A2D_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_A2D_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_A2D_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_A2D_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_A2D_TRACE_LEVEL=2
# CONFIG_BT_LOG_AVDT_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_AVDT_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_AVDT_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_AVDT_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_AVDT_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_AVDT_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_AVDT_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_AVDT_TRACE_LEVEL=2
# CONFIG_BT_LOG_AVCT_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_AVCT_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_AVCT_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_AVCT_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_AVCT_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_AVCT_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_AVCT_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_AVCT_TRACE_LEVEL=2
# CONFIG_BT_LOG_AVRC_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_AVRC_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_AVRC_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_AVRC_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_AVRC_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_AVRC_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_AVRC_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_AVRC_TRACE_LEVEL=2
# CONFIG_BT_LOG_MCA_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_MCA_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_MCA_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_MCA_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_MCA_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_MCA_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_MCA_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_MCA_TRACE_LEVEL=2
# CONFIG_BT_LOG_HID_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_HID_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_HID_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_HID_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_HID_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_HID_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_HID_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_HID_TRACE_LEVEL=2
# CONFIG_BT_LOG_APPL_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_APPL_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_APPL_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_APPL_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_APPL_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_APPL_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_APPL_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_APPL_TRACE_LEVEL=2
# CONFIG_BT_LOG_GATT_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_GATT_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_GATT_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_GATT_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_GATT_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_GATT_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_GATT_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_GATT_TRACE_LEVEL=2
# CONFIG_BT_LOG_SMP_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_SMP_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_SMP_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_SMP_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_SMP_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_SMP_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_SMP_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_SMP_TRACE_LEVEL=2
# CONFIG_BT_LOG_BTIF_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_BTIF_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_BTIF_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_BTIF_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_BTIF_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_BTIF_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_BTIF_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_BTIF_TRACE_LEVEL=2
# CONFIG_BT_LOG_BTC_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_BTC_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_BTC_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_BTC_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_BTC_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_BTC_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_BTC_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_BTC_TRACE_LEVEL=2
# CONFIG_BT_LOG_OSI_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_OSI_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_OSI_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_OSI_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_OSI_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_OSI_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_OSI_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_OSI_TRACE_LEVEL=2
# CONFIG_BT_LOG_BLUFI_TRACE_LEVEL_NONE is not set
# CONFIG_BT_LOG_BLUFI_TRACE_LEVEL_ERROR is not set
CONFIG_BT_LOG_BLUFI_TRACE_LEVEL_WARNING=y
# CONFIG_BT_LOG_BLUFI_TRACE_LEVEL_API is not set
# CONFIG_BT_LOG_BLUFI_TRACE_LEVEL_EVENT is not set
# CONFIG_BT_LOG_BLUFI_TRACE_LEVEL_DEBUG is not set
# CONFIG_BT_LOG_BLUFI_TRACE_LEVEL_VERBOSE is not set
CONFIG_BT_LOG_BLUFI_TRACE_LEVEL=2
# end of BT DEBUG LOG LEVEL

CONFIG_BT_ACL_CONNECTIONS=4
CONFIG_BT_MULTI_CONNECTION_ENBALE=y
# CONFIG_BT_ALLOCATION_FROM_SPIRAM_FIRST is not set
# CONFIG_BT_BLE_DYNAMIC_ENV_MEMORY is not set
# CONFIG_BT_BLE_HOST_QUEUE_CONG_CHECK is not set
CONFIG_BT_SMP_ENABLE=y
CONFIG_BT_BLE_ESTAB_LINK_CONN_TOUT=30
CONFIG_BT_MAX_DEVICE_NAME_LEN=32
# CONFIG_BT_BLE_RPA_SUPPORTED is not set
CONFIG_BT_RESERVE_DRAM=0xdb5c
# end of Bluedroid Options

CONFIG_BT_NIMBLE_USE_ESP_TIMER=y
# end of Bluetooth

Code to reproduce this issue

https://github.com/espressif/esp-idf/tree/master/examples/bluetooth/bluedroid/classic_bt/bt_spp_initiator with modified name and adress.

For the log file I also changed the code so that no name resolving is used, but esp_spp_start_discovery is called with the adress directly.
(As a quick solution I start SPP discovery with first GAP discovery result and cancel discovery - so just some lines needed to be commented out:

Changed adresses/names in main.c:

static const esp_spp_mode_t esp_spp_mode = ESP_SPP_MODE_CB;

static struct timeval time_new, time_old;
static long data_num = 0;

static const esp_spp_sec_t sec_mask = ESP_SPP_SEC_AUTHENTICATE;
static const esp_spp_role_t role_master = ESP_SPP_ROLE_MASTER;

esp_bd_addr_t peer_bd_addr =  { 0x20, 0x13, 0x01, 0x18, 0x02, 0x26 }; 

static uint8_t peer_bdname_len;
static char peer_bdname[ESP_BT_GAP_MAX_BDNAME_LEN + 1];
//static const char remote_device_name[] = "ESP_SPP_ACCEPTOR";
static const esp_bt_inq_mode_t inq_mode = ESP_BT_INQ_MODE_GENERAL_INQUIRY;
static const uint8_t inq_len = 30;
static const uint8_t inq_num_rsps = 0;
[...]

adapted function for the try without GAP name resolving in main.c:

static void esp_bt_gap_cb(esp_bt_gap_cb_event_t event, esp_bt_gap_cb_param_t *param)
{
    switch(event){
    case ESP_BT_GAP_DISC_RES_EVT:
        ESP_LOGI(SPP_TAG, "ESP_BT_GAP_DISC_RES_EVT");
        esp_log_buffer_hex(SPP_TAG, param->disc_res.bda, ESP_BD_ADDR_LEN);
        /* Find the target peer device name in the EIR data */
//        for (int i = 0; i < param->disc_res.num_prop; i++){
//            if (param->disc_res.prop[i].type == ESP_BT_GAP_DEV_PROP_EIR
//                && get_name_from_eir(param->disc_res.prop[i].val, peer_bdname, &peer_bdname_len)){
                esp_log_buffer_char(SPP_TAG, peer_bdname, peer_bdname_len);
                ESP_LOGI(SPP_TAG,"Dev-Name %s", peer_bdname);
//              if (strlen(remote_device_name) == peer_bdname_len
//                    && strncmp(peer_bdname, remote_device_name, peer_bdname_len) == 0) {
//                    memcpy(peer_bd_addr, param->disc_res.bda, ESP_BD_ADDR_LEN);
                    /* Have found the target peer device, cancel the previous GAP discover procedure. And go on
                     * dsicovering the SPP service on the peer device */
                    esp_bt_gap_cancel_discovery();
                    esp_spp_start_discovery(peer_bd_addr);
//                }
//            }
//        }
        break;

[...]

[euphi]

I tried to disable SSP in the IDF Config (unset CONFIG_BT_SSP_ENABLED) - this seem to solve (work around) the issue.

(Sorry, I also noticed that I already posted the config with disabled SSP in my initial issue description. The log is from a configuration with SSP enabled. The config is the one that works now for me)

So, the problem is with SSP and some (old) bluetooth chip (that I don't know - and I can't access it (mix of epoxy, shrink tube, hot glue..), but I guess it is similar or the same chip as used in HC-05 or HC-06 modules.

[BetterJincheng]

@euphi I tried between two ESP32 modules and found nothing wrong about initiator. If you want to connect ESP32 to other device, you should make sure that the two have a common way of pairing.
Turn to us if any questions. Thanks!

[euphi]

With SSP disabled in sdkconfig, pairing works fine.

However, with SSP enabled in config, pairing (or connecting to already paired device) does NOT work - even if I don't set SSP related configuration/parameters. (When using the Initiator example) - or no call to enableSSP() when using Arduino-ESP32s BluetoothSerial.

So, I think SSP has a negative impact on pairing/connecting on some BT device, even when SSP is not used.

[ferbar]

I want to establish a SPP connection from an ESP32 to a linux-pc with usb bt-dongle or raspberry pi zero w (both bluez). I'm having the same troubles as described by @euphi:

I can reproduce the error in bt_spp_initiator when Secure Simple Pairing is enabled. Changing the spp_sec mode to NONE didn't change anything.

static const esp_spp_sec_t sec_mask = ESP_SPP_SEC_NONE;

Logs:

I (2931) BT_RFCOMM: RFCOMM_CreateConnection(): scn:30, dlci:60, is_server:0 mtu:990, p_mcb:0x0, p_port:0x3ffc6bb4
I (2941) BT_L2CAP: L2CA_ErtmConnectReq()  PSM: 0x0003  BDA: 0002720376fc  p_ertm_info: 0x0 allowed:0x0 preferred:0
E (2951) BT_BTM: btm_sec_l2cap_access_req: (initiator) remote features unknown!!sec_flags:0x88

I (2961) BT_L2CAP: L2CAP - L2CA_conn_req(psm: 0x0003) returned CID: 0x0041
I (2971) BT_RFCOMM: PORT_SetEventCallback() handle:2
I (2971) BT_RFCOMM: PORT_SetEventMask() handle:2 mask:0x30005
I (2981) BT_RFCOMM: PORT_GetState() handle:2
I (2981) BT_RFCOMM: PORT_SetState() handle:2
I (2991) BT_RFCOMM: PORT_SetState() handle:2 FC_TYPE:0xc
I (2991) SPP_INITIATOR_DEMO: ESP_SPP_CL_INIT_EVT
I (7111) BT_L2CAP: L2CAP - Calling Disconnect_Ind_Cb(), CID: 0x0041  No Conf Needed

Looks ais if it's from here, however the code didn't change recently.
remote features unknown!! :
https://github.com/espressif/esp-idf/blob/master/components/bt/host/bluedroid/stack/btm/btm_sec.c#L2280

The program running on linux is the spp_echo_server: https://gist.github.com/ukBaz/217875c83c2535d22a16ba38fc8f2a91

bt_spp_initiator was additionaly modified to connect directly to a mac and not send too much data.

Update:
removing the call to esp_bt_gap_set_security_param changed that I could connect to bluetooth 4.0 devices: Raspberry Pi Zero W and several different USB dongles as well as a bluetooth 1.1 USB dongle.

BT_BTM: btm_sec_l2cap_access_req: (initiator) remote features unknown!!sec_flags:0x88 persists for the bluetooth 2.0 USB dongles (Cambridge Silicon Radio, 0x0a12:0x0001)

@BetterJincheng: it would be great if "btm_sec_l2cap_access_req: (initiator) remote features unknown!!" would trgger a callback function

thanks!