espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.7k stars 7.29k forks source link

Bluedroid SPP acceptor: `esp_spp_write`-en data comes back as `ESP_SPP_DATA_IND_EVT` after client closes serial port (IDFGH-11931) #13011

Closed LaXiS96 closed 9 months ago

LaXiS96 commented 9 months ago

Answers checklist.

IDF version.

v5.1.2 release

Espressif SoC revision.

ESP32-D0WDQ6 (revision v1.0)

Operating System used.

Linux

How did you build your project?

VS Code IDE

If you are using Windows, please specify command line type.

None

Development Kit.

ESP32-DevKitC V4

Power Supply used.

USB

What is the expected behavior?

See implementation here (my repo). With the ESP32 accepting Bluetooth SPP connections, a Linux client connects to the RFCOMM serial port, opens it and then closes it without disconnecting from the ESP32. The expected behavior is that ESP_SPP_DATA_IND_EVT events should only be received when the connected client has the serial port open and is actually sending data.

What is the actual behavior?

What happens instead is that after the serial port is closed, ESP_SPP_DATA_IND_EVT events are notified with the same data that is concurrently being written with esp_spp_write from another task. See the log below (BT tag):

Steps to reproduce.

  1. Connect to ESP32 Bluetooth serial port from PC (on Linux this creates the /dev/rfcomm0 device)
  2. Open serial port on PC with preferred software (e.g. tio or CuteCom)
  3. (In my project's case, send configuration commands to start receiving data: S6\r and O\r, but a CANbus source is needed)
  4. Close serial port on PC (e.g. by closing the terminal or GUI), but do not disconnect the Bluetooth device
  5. If the client opens the serial port again, everything returns to normal; if it closes it again, the issue occurs again

Debug Logs.

--- esp-idf-monitor 1.3.4 on /dev/ttyUSB0 115200 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
ets Jun  8 2016 00:22:57

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:7084
ho 0 tail 12 room 4
load:0x40078000,len:15584
load:0x40080400,len:4
0x40080400: _init at ??:?

load:0x40080404,len:3876
entry 0x4008064c
I (31) boot: ESP-IDF v5.1.2-dirty 2nd stage bootloader
I (31) boot: compile time Jan 17 2024 20:41:29
I (31) boot: Multicore bootloader
I (36) boot: chip revision: v1.0
I (39) boot.esp32: SPI Speed      : 40MHz
I (44) boot.esp32: SPI Mode       : DIO
I (48) boot.esp32: SPI Flash Size : 4MB
I (53) boot: Enabling RNG early entropy source...
I (58) boot: Partition Table:
I (62) boot: ## Label            Usage          Type ST Offset   Length
I (69) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (77) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (84) boot:  2 factory          factory app      00 00 00010000 00100000
I (92) boot: End of partition table
I (96) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=1cc84h (117892) map
I (147) esp_image: segment 1: paddr=0002ccac vaddr=3ffbdb60 size=0336ch ( 13164) load
I (152) esp_image: segment 2: paddr=00030020 vaddr=400d0020 size=71e5ch (466524) map
I (321) esp_image: segment 3: paddr=000a1e84 vaddr=3ffc0ecc size=01534h (  5428) load
I (324) esp_image: segment 4: paddr=000a33c0 vaddr=40080000 size=19eb8h (106168) load
I (384) boot: Loaded app from partition at offset 0x10000
I (384) boot: Disabling RNG early entropy source...
I (396) cpu_start: Multicore app
I (396) cpu_start: Pro cpu up.
I (396) cpu_start: Starting app cpu, entry point is 0x40081520
0x40081520: call_start_cpu1 at /home/laxis/esp/esp-idf/components/esp_system/port/cpu_start.c:157

I (0) cpu_start: App cpu up.
I (414) cpu_start: Pro cpu start user code
I (414) cpu_start: cpu freq: 240000000 Hz
I (414) cpu_start: Application information:
I (419) cpu_start: Project name:     esp32-obd2
I (424) cpu_start: App version:      14f186a-dirty
I (429) cpu_start: Compile time:     Jan 17 2024 20:41:31
I (435) cpu_start: ELF file SHA256:  7901b332b2c2a96a...
I (441) cpu_start: ESP-IDF:          v5.1.2-dirty
I (447) cpu_start: Min chip rev:     v0.0
I (451) cpu_start: Max chip rev:     v3.99 
I (456) cpu_start: Chip rev:         v1.0
I (461) heap_init: Initializing. RAM available for dynamic allocation:
I (468) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (474) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (480) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (487) heap_init: At 3FFC84A0 len 00017B60 (94 KiB): DRAM
I (493) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (499) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (505) heap_init: At 40099EB8 len 00006148 (24 KiB): IRAM
I (513) spi_flash: detected chip: generic
I (516) spi_flash: flash io: dio
I (521) coexist: coex firmware version: b6d5e8c
I (526) app_start: Starting scheduler on CPU0
I (531) app_start: Starting scheduler on CPU1
I (531) main_task: Started on CPU0
I (541) main_task: Calling app_main()
I (581) BTDM_INIT: BT controller compile version [ec4ac65]
I (581) BTDM_INIT: Bluetooth MAC: 7c:9e:bd:f6:41:92
I (591) phy_init: phy_version 4780,16b31a7,Sep 22 2023,20:42:16
I (1011) BT: ESP_SPP_INIT_EVT
I (1021) BT: ESP_SPP_START_EVT handle:129 sec_id:55 scn:1
I (1021) BT: GAP event:10
I (1021) BT: initialized
I (1021) CAN: initialized
I (1021) SLCAN: initialized
I (1031) main_task: Returned from app_main()
W (5831) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
I (5831) BT: GAP event:16
W (6171) BT_APPL: new conn_srvc id:26, app_id:255
W (6171) BT_APPL: bta_dm_pm_ssr conn_srvc id:26, app_id:255
W (6171) BT_APPL: bta_dm_pm_ssr:2, lat:1200
I (6181) BT: ESP_SPP_SRV_OPEN_EVT status:0 handle:129, rem_bda:[80:19:34:16:ba:b0]
I (10851) BT: ESP_SPP_DATA_IND_EVT length:3
I (10851) SLCAN: serial received bytes:3
I (10851) SLCAN: command "S6"
I (10851) SLCAN: respond ok
I (10861) SLCAN: serial transmit bytes:1
I (10871) BT: write messages:1 bytes:1
I (11991) BT: ESP_SPP_DATA_IND_EVT length:2
I (11991) SLCAN: serial received bytes:2
I (11991) SLCAN: command "O"
I (12001) CAN: opening
I (12001) gpio: GPIO[22]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (12011) gpio: GPIO[21]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (12021) CAN: opened
I (12021) SLCAN: respond ok
I (12021) SLCAN: serial transmit bytes:1
I (12031) BT: write messages:1 bytes:1
W (19231) BT_HCI: hci cmd send: sniff: hdl 0x80, intv(400 800)
W (19311) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 800, status 0x0
I (19311) BT: GAP event:13
W (20481) BT_HCI: hcif ssr evt: st 0x0, hdl 0x80, tx_lat 800 rx_lat 800
I (21651) CAN: received message id:1365
I (21651) SLCAN: serial transmit bytes:14
I (21661) BT: write messages:1 bytes:14
W (21661) BT_HCI: hci cmd send: unsniff: hdl 0x80
W (22471) BT_HCI: hcif mode change: hdl 0x80, mode 0, intv 0, status 0x0
I (22471) BT: GAP event:13
I (23641) CAN: received message id:1365
I (23641) SLCAN: serial transmit bytes:14
I (23651) BT: write messages:1 bytes:14
I (25641) CAN: received message id:1365
I (25641) SLCAN: serial transmit bytes:14
I (25651) BT: write messages:1 bytes:14
I (27641) CAN: received message id:1365
I (27641) SLCAN: serial transmit bytes:14
I (27651) BT: write messages:1 bytes:14
I (29641) CAN: received message id:1365
I (29641) SLCAN: serial transmit bytes:14
I (29651) BT: write messages:1 bytes:14
I (31641) CAN: received message id:1365
I (31641) SLCAN: serial transmit bytes:14
I (31651) BT: write messages:1 bytes:14
I (33641) CAN: received message id:1365
I (33641) SLCAN: serial transmit bytes:14
I (33651) BT: write messages:1 bytes:14
I (35641) CAN: received message id:1365
I (35641) SLCAN: serial transmit bytes:14
I (35651) BT: write messages:1 bytes:14
I (37641) CAN: received message id:1365
I (37641) SLCAN: serial transmit bytes:14
I (37651) BT: write messages:1 bytes:14
I (39641) CAN: received message id:1365
I (39641) SLCAN: serial transmit bytes:14
I (39651) BT: write messages:1 bytes:14
I (39691) BT: ESP_SPP_DATA_IND_EVT length:1
I (39691) SLCAN: serial received bytes:1
I (39701) BT: ESP_SPP_DATA_IND_EVT length:1
I (39701) SLCAN: serial received bytes:1
I (39701) BT: ESP_SPP_DATA_IND_EVT length:1
I (39701) SLCAN: serial received bytes:1
I (39701) BT: ESP_SPP_DATA_IND_EVT length:1
I (39721) SLCAN: serial received bytes:1
I (39721) BT: ESP_SPP_DATA_IND_EVT length:1
I (39721) SLCAN: serial received bytes:1
I (39721) BT: ESP_SPP_DATA_IND_EVT length:1
I (39731) SLCAN: serial received bytes:1
I (39731) BT: ESP_SPP_DATA_IND_EVT length:1
I (39741) SLCAN: serial received bytes:1
I (39741) BT: ESP_SPP_DATA_IND_EVT length:1
I (39751) SLCAN: serial received bytes:1
I (39751) BT: ESP_SPP_DATA_IND_EVT length:1
I (39761) SLCAN: serial received bytes:1
I (39761) BT: ESP_SPP_DATA_IND_EVT length:1
I (39771) SLCAN: serial received bytes:1
I (39801) BT: ESP_SPP_DATA_IND_EVT length:1
I (39801) SLCAN: serial received bytes:1
I (39801) BT: ESP_SPP_DATA_IND_EVT length:1
I (39801) SLCAN: serial received bytes:1
I (39801) BT: ESP_SPP_DATA_IND_EVT length:1
I (39811) SLCAN: serial received bytes:1
I (39811) BT: ESP_SPP_DATA_IND_EVT length:2
I (39821) SLCAN: serial received bytes:2
I (39831) SLCAN: command "t55540D0E0A0D"
I (39831) SLCAN: respond ok data="z"
I (39841) SLCAN: serial transmit bytes:2
I (39851) BT: write messages:1 bytes:2
I (39881) BT: ESP_SPP_DATA_IND_EVT length:1
I (39881) SLCAN: serial received bytes:1
I (39881) BT: ESP_SPP_DATA_IND_EVT length:2
I (39891) SLCAN: serial received bytes:2
I (39891) SLCAN: command "z"
I (39901) SLCAN: respond error
I (39901) SLCAN: serial transmit bytes:1
I (39911) BT: write messages:1 bytes:1
I (39951) BT: ESP_SPP_DATA_IND_EVT length:1
I (39951) SLCAN: serial received bytes:1
I (39951) BT: ESP_SPP_DATA_IND_EVT length:1
I (39951) SLCAN: serial received bytes:1
I (41641) CAN: received message id:1365
I (41641) SLCAN: serial transmit bytes:14
I (41651) BT: write messages:1 bytes:14
I (41701) BT: ESP_SPP_DATA_IND_EVT length:1
I (41701) SLCAN: serial received bytes:1
I (41701) BT: ESP_SPP_DATA_IND_EVT length:1
I (41701) SLCAN: serial received bytes:1
I (41701) BT: ESP_SPP_DATA_IND_EVT length:1
I (41711) SLCAN: serial received bytes:1
I (41711) BT: ESP_SPP_DATA_IND_EVT length:1
I (41721) SLCAN: serial received bytes:1
I (41721) BT: ESP_SPP_DATA_IND_EVT length:1
I (41731) SLCAN: serial received bytes:1
I (41731) BT: ESP_SPP_DATA_IND_EVT length:1
I (41741) BT: ESP_SPP_DATA_IND_EVT length:1
I (41741) SLCAN: serial received bytes:1
I (41751) SLCAN: serial received bytes:1
I (41741) BT: ESP_SPP_DATA_IND_EVT length:1
I (41761) SLCAN: serial received bytes:1
I (41761) BT: ESP_SPP_DATA_IND_EVT length:1
I (41771) SLCAN: serial received bytes:1
I (41771) BT: ESP_SPP_DATA_IND_EVT length:1
I (41771) SLCAN: serial received bytes:1
I (41811) BT: ESP_SPP_DATA_IND_EVT length:1
I (41811) SLCAN: serial received bytes:1
I (41811) BT: ESP_SPP_DATA_IND_EVT length:1
I (41811) SLCAN: serial received bytes:1
I (41811) BT: ESP_SPP_DATA_IND_EVT length:1
I (41821) SLCAN: serial received bytes:1
I (41821) BT: ESP_SPP_DATA_IND_EVT length:2
I (41831) SLCAN: serial received bytes:2
I (41831) SLCAN: command "^Gt55540D0E0A0D"
I (41841) SLCAN: respond error
I (41841) SLCAN: serial transmit bytes:1
I (41851) BT: write messages:1 bytes:1
I (41871) BT: ESP_SPP_DATA_IND_EVT length:1
I (41871) SLCAN: serial received bytes:1
I (41871) BT: ESP_SPP_DATA_IND_EVT length:1
I (41871) SLCAN: serial received bytes:1

More Information.

No response

boblane1 commented 9 months ago

Hi @LaXiS96,

It is unlikely that no ESP_SPP_CLOSE_EVT event comes when the client closes the serial port. I have tried with tio or cutecom, but neither could reproduce the issue. Could you please simplify your project to reproduce the issue and detail the sending behavior on client side?

Thanks.

LaXiS96 commented 9 months ago

I can reproduce it outside my original project, but only on my Linux machine and not on Windows.

Based on code and logs below:

I am noticing that the DATA_IND data contains the entire test message plus an additional ^J (which is the terminal representation of \n), it looks like the Linux client is actively sending back the data?

On Windows I have no such issue, closing the serial port logs this as expected:

W (47635) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:1 state 2 closed: Closed (res: 19)
I (47645) spp: ESP_SPP_CLOSE_EVT
W (47655) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x40 current:0x0
W (47655) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x40
sdkconfig.defaults ```plain CONFIG_BT_ENABLED=y CONFIG_BTDM_CTRL_MODE_BR_EDR_ONLY=y CONFIG_BT_BLE_ENABLED=n CONFIG_BT_CLASSIC_ENABLED=y CONFIG_BT_SPP_ENABLED=y CONFIG_BT_SSP_ENABLED=n ```
main.c ```c #include #include #include "freertos/FreeRTOS.h" #include "freertos/task.h" #include "freertos/semphr.h" #include "nvs_flash.h" #include "esp_log.h" #include "esp_bt.h" #include "esp_bt_main.h" #include "esp_bt_device.h" #include "esp_gap_bt_api.h" #include "esp_spp_api.h" static uint32_t sppHandle = 0; static char *bda2str(uint8_t *bda, char *str, size_t size) { if (bda == NULL || str == NULL || size < 18) return NULL; uint8_t *p = bda; sprintf(str, "%02x:%02x:%02x:%02x:%02x:%02x", p[0], p[1], p[2], p[3], p[4], p[5]); return str; } static void gapCallback(esp_bt_gap_cb_event_t event, esp_bt_gap_cb_param_t *param) { switch (event) { case ESP_BT_GAP_AUTH_CMPL_EVT: ESP_LOGI("gap", "ESP_BT_GAP_AUTH_CMPL_EVT"); if (param->auth_cmpl.stat == ESP_BT_STATUS_SUCCESS) { ESP_LOGI("gap", "authentication success: %s", param->auth_cmpl.device_name); esp_log_buffer_hex("gap", param->auth_cmpl.bda, ESP_BD_ADDR_LEN); } else { ESP_LOGE("gap", "authentication failed, status:%d", param->auth_cmpl.stat); } break; default: ESP_LOGI("gap", "event:%d", event); } } static void sppCallback(esp_spp_cb_event_t event, esp_spp_cb_param_t *param) { char bda_str[18] = {0}; switch (event) { case ESP_SPP_INIT_EVT: if (param->init.status == ESP_SPP_SUCCESS) { ESP_LOGI("spp", "ESP_SPP_INIT_EVT"); esp_spp_start_srv(ESP_SPP_SEC_AUTHENTICATE, ESP_SPP_ROLE_SLAVE, 0, "SPP"); } else { ESP_LOGE("spp", "ESP_SPP_INIT_EVT status:%d", param->init.status); } break; case ESP_SPP_CLOSE_EVT: ESP_LOGI("spp", "ESP_SPP_CLOSE_EVT"); sppHandle = 0; break; case ESP_SPP_START_EVT: if (param->start.status == ESP_SPP_SUCCESS) { ESP_LOGI("spp", "ESP_SPP_START_EVT handle:%" PRIu32 " sec_id:%d scn:%d", param->start.handle, param->start.sec_id, param->start.scn); esp_bt_dev_set_device_name("ESP32"); esp_bt_gap_set_scan_mode(ESP_BT_CONNECTABLE, ESP_BT_GENERAL_DISCOVERABLE); } else { ESP_LOGE("spp", "ESP_SPP_START_EVT status:%d", param->start.status); } break; case ESP_SPP_DATA_IND_EVT: ESP_LOGI("spp", "ESP_SPP_DATA_IND_EVT length:%d", param->data_ind.len); ESP_LOG_BUFFER_HEXDUMP("spp", param->data_ind.data, param->data_ind.len, ESP_LOG_INFO); break; case ESP_SPP_CONG_EVT: ESP_LOGW("spp", "ESP_SPP_CONG_EVT status:%d cong:%d", param->cong.status, param->cong.cong); break; case ESP_SPP_WRITE_EVT: ESP_LOGW("spp", "ESP_SPP_WRITE_EVT status:%d cong:%d len:%d", param->write.status, param->write.cong, param->write.len); break; case ESP_SPP_SRV_OPEN_EVT: ESP_LOGI("spp", "ESP_SPP_SRV_OPEN_EVT status:%d handle:%" PRIu32 ", rem_bda:[%s]", param->srv_open.status, param->srv_open.handle, bda2str(param->srv_open.rem_bda, bda_str, sizeof(bda_str))); sppHandle = param->srv_open.handle; break; default: ESP_LOGI("spp", "event:%d", event); } } void app_main(void) { esp_err_t ret = nvs_flash_init(); if (ret == ESP_ERR_NVS_NO_FREE_PAGES || ret == ESP_ERR_NVS_NEW_VERSION_FOUND) { ESP_ERROR_CHECK(nvs_flash_erase()); ret = nvs_flash_init(); } ESP_ERROR_CHECK(ret); ESP_ERROR_CHECK(esp_bt_controller_mem_release(ESP_BT_MODE_BLE)); esp_bt_controller_config_t bt_cfg = BT_CONTROLLER_INIT_CONFIG_DEFAULT(); esp_spp_cfg_t spp_cfg = { .mode = ESP_SPP_MODE_CB, .enable_l2cap_ertm = true, .tx_buffer_size = 0, }; ESP_ERROR_CHECK(esp_bt_controller_init(&bt_cfg)); ESP_ERROR_CHECK(esp_bt_controller_enable(ESP_BT_MODE_CLASSIC_BT)); ESP_ERROR_CHECK(esp_bluedroid_init()); ESP_ERROR_CHECK(esp_bluedroid_enable()); ESP_ERROR_CHECK(esp_bt_gap_register_callback(gapCallback)); ESP_ERROR_CHECK(esp_spp_register_callback(sppCallback)); ESP_ERROR_CHECK(esp_spp_enhanced_init(&spp_cfg)); ESP_ERROR_CHECK(esp_bt_gap_set_pin(ESP_BT_PIN_TYPE_FIXED, 4, (esp_bt_pin_code_t){'0', '0', '0', '0'})); const char *data = "0123456789\r\n"; const size_t len = strlen(data); while (true) { if (sppHandle > 0) ESP_ERROR_CHECK(esp_spp_write(sppHandle, len, (uint8_t *)data)); else ESP_LOGI("main", "discard"); vTaskDelay(pdMS_TO_TICKS(1000)); } } ```
Log ```plain ets Jun 8 2016 00:22:57 rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT) flash read err, 1000 ets_main.c 371 ets Jun 8 2016 00:22:57 rst:0x10 (RTCWDT_RTC_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT) configsip: 0, SPIWP:0xee clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00 mode:DIO, clock div:2 load:0x3fff0030,len:7080 load:0x40078000,len:15584 load:0x40080400,len:4 0x40080400: _init at ??:? ho 8 tail 4 room 4 load:0x40080404,len:3876 entry 0x4008064c I (31) boot: ESP-IDF v5.1.2 2nd stage bootloader I (31) boot: compile time Jan 19 2024 10:50:47 I (31) boot: Multicore bootloader I (35) boot: chip revision: v1.0 I (39) boot.esp32: SPI Speed : 40MHz I (43) boot.esp32: SPI Mode : DIO I (48) boot.esp32: SPI Flash Size : 2MB I (52) boot: Enabling RNG early entropy source... I (58) boot: Partition Table: I (61) boot: ## Label Usage Type ST Offset Length I (69) boot: 0 nvs WiFi data 01 02 00009000 00006000 I (76) boot: 1 phy_init RF data 01 01 0000f000 00001000 I (84) boot: 2 factory factory app 00 00 00010000 00100000 I (91) boot: End of partition table I (95) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=1b95ch (112988) map I (145) esp_image: segment 1: paddr=0002b984 vaddr=3ffbdb60 size=04694h ( 18068) load I (152) esp_image: segment 2: paddr=00030020 vaddr=400d0020 size=6e7d4h (452564) map I (316) esp_image: segment 3: paddr=0009e7fc vaddr=3ffc21f4 size=00184h ( 388) load I (316) esp_image: segment 4: paddr=0009e988 vaddr=40080000 size=19798h (104344) load I (378) boot: Loaded app from partition at offset 0x10000 I (378) boot: Disabling RNG early entropy source... I (389) cpu_start: Multicore app I (390) cpu_start: Pro cpu up. I (390) cpu_start: Starting app cpu, entry point is 0x40081498 0x40081498: call_start_cpu1 at C:/Users/LaXiS/esp/esp-idf/components/esp_system/port/cpu_start.c:157 I (0) cpu_start: App cpu up. I (408) cpu_start: Pro cpu start user code I (408) cpu_start: cpu freq: 160000000 Hz I (408) cpu_start: Application information: I (412) cpu_start: Project name: template-app I (418) cpu_start: App version: 1 I (422) cpu_start: Compile time: Jan 19 2024 10:50:35 I (428) cpu_start: ELF file SHA256: 49b487acc744a55e... I (434) cpu_start: ESP-IDF: v5.1.2 I (439) cpu_start: Min chip rev: v0.0 I (444) cpu_start: Max chip rev: v3.99 I (449) cpu_start: Chip rev: v1.0 I (454) heap_init: Initializing. RAM available for dynamic allocation: I (461) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM I (467) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM I (473) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM I (479) heap_init: At 3FFC8268 len 00017D98 (95 KiB): DRAM I (485) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM I (491) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM I (498) heap_init: At 40099798 len 00006868 (26 KiB): IRAM I (505) spi_flash: detected chip: gd I (508) spi_flash: flash io: dio W (512) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header. I (526) coexist: coex firmware version: b6d5e8c I (531) app_start: Starting scheduler on CPU0 (536) app_start: Starting scheduler on CPU1 mI (536) main_task: Started on CPU0 I (546) main_task: Calling app_main() I (586) BTDM_INIT: BT controller compile version [ec4ac65] I (586) BTDM_INIT: Bluetooth MAC: 30:ae:a4:27:c3:ba I (596) phy_init: phy_version 4780,16b31a7,Sep 22 2023,20:42:16 I (1216) spp: ESP_SPP_INIT_EVT I (1216) spp: ESP_SPP_START_EVT handle:129 sec_id:55 scn:1 I (1226) gap: event:10 I (1226) main: discard I (2226) main: discard I (3226) main: discard W (3426) BT_HCI: hcif conn complete: hdl 0x80, st 0x0 I (3436) gap: event:16 W (3756) BT_APPL: new conn_srvc id:26, app_id:255 W (3756) BT_APPL: bta_dm_pm_ssr conn_srvc id:26, app_id:255 W (3766) BT_APPL: bta_dm_pm_ssr:2, lat:1200 I (3766) spp: ESP_SPP_SRV_OPEN_EVT status:0 handle:129, rem_bda:[80:19:34:16:ba:b0] W (4226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 I (4276) spp: ESP_SPP_DATA_IND_EVT length:1 I (4276) spp: 0x3ffcfda4 30 |0| I (4286) spp: ESP_SPP_DATA_IND_EVT length:1 I (4286) spp: 0x3ffcfdc0 31 |1| I (4296) spp: ESP_SPP_DATA_IND_EVT length:1 I (4296) spp: 0x3ffcfddc 32 |2| I (4306) spp: ESP_SPP_DATA_IND_EVT length:1 I (4316) spp: 0x3ffcfdf8 33 |3| I (4316) spp: ESP_SPP_DATA_IND_EVT length:1 I (4326) spp: 0x3ffcfe9c 34 |4| I (4336) spp: ESP_SPP_DATA_IND_EVT length:1 I (4336) spp: 0x3ffcfeb8 35 |5| I (4346) spp: ESP_SPP_DATA_IND_EVT length:1 I (4346) spp: 0x3ffcff7c 36 |6| I (4356) spp: ESP_SPP_DATA_IND_EVT length:1 I (4366) spp: 0x3ffcff98 37 |7| I (4376) spp: ESP_SPP_DATA_IND_EVT length:1 I (4376) spp: 0x3ffcffb4 38 |8| I (4386) spp: ESP_SPP_DATA_IND_EVT length:1 I (4386) spp: 0x3ffcffd0 39 |9| I (4436) spp: ESP_SPP_DATA_IND_EVT length:2 I (4436) spp: 0x3ffcfda4 0d 0a |..| I (4446) spp: ESP_SPP_DATA_IND_EVT length:1 I (4446) spp: 0x3ffcfdc0 5e |^| I (4456) spp: ESP_SPP_DATA_IND_EVT length:1 I (4456) spp: 0x3ffcfddc 4a |J| W (5226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 I (5266) spp: ESP_SPP_DATA_IND_EVT length:1 I (5266) spp: 0x3ffcfda4 30 |0| I (5266) spp: ESP_SPP_DATA_IND_EVT length:1 I (5276) spp: 0x3ffcfdc0 31 |1| I (5286) spp: ESP_SPP_DATA_IND_EVT length:1 I (5286) spp: 0x3ffcfddc 32 |2| I (5296) spp: ESP_SPP_DATA_IND_EVT length:1 I (5296) spp: 0x3ffcfdf8 33 |3| I (5306) spp: ESP_SPP_DATA_IND_EVT length:1 I (5316) spp: 0x3ffcfe9c 34 |4| I (5316) spp: ESP_SPP_DATA_IND_EVT length:1 I (5326) spp: 0x3ffcfeb8 35 |5| I (5336) spp: ESP_SPP_DATA_IND_EVT length:1 I (5336) spp: 0x3ffcff7c 36 |6| I (5346) spp: ESP_SPP_DATA_IND_EVT length:1 I (5356) spp: 0x3ffcff98 37 |7| I (5356) spp: ESP_SPP_DATA_IND_EVT length:1 I (5366) spp: 0x3ffcffb4 38 |8| I (5376) spp: ESP_SPP_DATA_IND_EVT length:1 I (5376) spp: 0x3ffcffd0 39 |9| I (5426) spp: ESP_SPP_DATA_IND_EVT length:2 I (5426) spp: 0x3ffcfda4 0d 0a |..| I (5426) spp: ESP_SPP_DATA_IND_EVT length:1 I (5436) spp: 0x3ffcfdc0 5e |^| I (5446) spp: ESP_SPP_DATA_IND_EVT length:1 I (5446) spp: 0x3ffcfddc 4a |J| W (6226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 I (6246) spp: ESP_SPP_DATA_IND_EVT length:1 I (6256) spp: 0x3ffcfda4 30 |0| I (6256) spp: ESP_SPP_DATA_IND_EVT length:1 I (6256) spp: 0x3ffcfdc0 31 |1| I (6266) spp: ESP_SPP_DATA_IND_EVT length:1 I (6266) spp: 0x3ffcfddc 32 |2| I (6276) spp: ESP_SPP_DATA_IND_EVT length:1 I (6286) spp: 0x3ffcfdf8 33 |3| I (6296) spp: ESP_SPP_DATA_IND_EVT length:1 I (6296) spp: 0x3ffcfe9c 34 |4| I (6306) spp: ESP_SPP_DATA_IND_EVT length:1 I (6306) spp: 0x3ffcfeb8 35 |5| I (6316) spp: ESP_SPP_DATA_IND_EVT length:1 I (6326) spp: 0x3ffcff7c 36 |6| I (6326) spp: ESP_SPP_DATA_IND_EVT length:1 I (6336) spp: 0x3ffcff98 37 |7| I (6346) spp: ESP_SPP_DATA_IND_EVT length:1 I (6346) spp: 0x3ffcffb4 38 |8| I (6356) spp: ESP_SPP_DATA_IND_EVT length:1 I (6356) spp: 0x3ffcffd0 39 |9| I (6416) spp: ESP_SPP_DATA_IND_EVT length:2 I (6416) spp: 0x3ffcfda4 0d 0a |..| I (6416) spp: ESP_SPP_DATA_IND_EVT length:1 I (6416) spp: 0x3ffcfdc0 5e |^| I (6426) spp: ESP_SPP_DATA_IND_EVT length:1 I (6436) spp: 0x3ffcfddc 4a |J| W (7226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 W (8226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 W (9226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 W (10226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 W (11226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 W (12226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 W (13226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 W (14226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 W (15226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 I (15276) spp: ESP_SPP_DATA_IND_EVT length:1 I (15276) spp: 0x3ffcfda4 30 |0| I (15276) spp: ESP_SPP_DATA_IND_EVT length:1 I (15286) spp: 0x3ffcfdc0 31 |1| I (15296) spp: ESP_SPP_DATA_IND_EVT length:1 I (15296) spp: 0x3ffcfdec 32 |2| I (15306) spp: ESP_SPP_DATA_IND_EVT length:1 I (15306) spp: 0x3ffcfe08 33 |3| I (15316) spp: ESP_SPP_DATA_IND_EVT length:1 I (15326) spp: 0x3ffcff54 34 |4| I (15336) spp: ESP_SPP_DATA_IND_EVT length:1 I (15336) spp: 0x3ffcff70 35 |5| I (15346) spp: ESP_SPP_DATA_IND_EVT length:1 I (15346) spp: 0x3ffcff8c 36 |6| I (15356) spp: ESP_SPP_DATA_IND_EVT length:1 I (15366) spp: 0x3ffcffa8 37 |7| I (15366) spp: ESP_SPP_DATA_IND_EVT length:1 I (15376) spp: 0x3ffcffc4 38 |8| I (15386) spp: ESP_SPP_DATA_IND_EVT length:1 I (15386) spp: 0x3ffcffe0 39 |9| I (15436) spp: ESP_SPP_DATA_IND_EVT length:2 I (15436) spp: 0x3ffcfda4 0d 0a |..| I (15436) spp: ESP_SPP_DATA_IND_EVT length:1 I (15446) spp: 0x3ffcfdc0 5e |^| I (15456) spp: ESP_SPP_DATA_IND_EVT length:1 I (15456) spp: 0x3ffcfddc 4a |J| W (16226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 I (16256) spp: ESP_SPP_DATA_IND_EVT length:1 I (16256) spp: 0x3ffcfda4 30 |0| I (16256) spp: ESP_SPP_DATA_IND_EVT length:1 I (16266) spp: 0x3ffcfdc0 31 |1| I (16266) spp: ESP_SPP_DATA_IND_EVT length:1 I (16276) spp: 0x3ffcfddc 32 |2| I (16286) spp: ESP_SPP_DATA_IND_EVT length:1 I (16286) spp: 0x3ffcfdf8 33 |3| I (16296) spp: ESP_SPP_DATA_IND_EVT length:1 I (16296) spp: 0x3ffcfe9c 34 |4| I (16306) spp: ESP_SPP_DATA_IND_EVT length:1 I (16316) spp: 0x3ffcfeb8 35 |5| I (16326) spp: ESP_SPP_DATA_IND_EVT length:1 I (16326) spp: 0x3ffcff7c 36 |6| I (16336) spp: ESP_SPP_DATA_IND_EVT length:1 I (16336) spp: 0x3ffcff98 37 |7| I (16346) spp: ESP_SPP_DATA_IND_EVT length:1 I (16356) spp: 0x3ffcffb4 38 |8| I (16366) spp: ESP_SPP_DATA_IND_EVT length:1 I (16366) spp: 0x3ffcffd0 39 |9| I (16416) spp: ESP_SPP_DATA_IND_EVT length:2 I (16416) spp: 0x3ffcfda4 0d 0a |..| I (16416) spp: ESP_SPP_DATA_IND_EVT length:1 I (16416) spp: 0x3ffcfdc0 5e |^| I (16426) spp: ESP_SPP_DATA_IND_EVT length:1 I (16436) spp: 0x3ffcfddc 4a |J| W (17226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 I (17256) spp: ESP_SPP_DATA_IND_EVT length:1 I (17266) spp: 0x3ffcfda4 30 |0| I (17266) spp: ESP_SPP_DATA_IND_EVT length:1 I (17266) spp: 0x3ffcfdc0 31 |1| I (17276) spp: ESP_SPP_DATA_IND_EVT length:1 I (17286) spp: 0x3ffcfddc 32 |2| I (17286) spp: ESP_SPP_DATA_IND_EVT length:1 I (17296) spp: 0x3ffcfdf8 33 |3| I (17306) spp: ESP_SPP_DATA_IND_EVT length:1 I (17306) spp: 0x3ffcfe9c 34 |4| I (17316) spp: ESP_SPP_DATA_IND_EVT length:1 I (17316) spp: 0x3ffcfeb8 35 |5| I (17326) spp: ESP_SPP_DATA_IND_EVT length:1 I (17336) spp: 0x3ffcff7c 36 |6| I (17346) spp: ESP_SPP_DATA_IND_EVT length:1 I (17346) spp: 0x3ffcff98 37 |7| I (17356) spp: ESP_SPP_DATA_IND_EVT length:1 I (17356) spp: 0x3ffcffb4 38 |8| I (17366) spp: ESP_SPP_DATA_IND_EVT length:1 I (17376) spp: 0x3ffcfda4 39 |9| I (17416) spp: ESP_SPP_DATA_IND_EVT length:2 I (17416) spp: 0x3ffcfda4 0d 0a |..| I (17416) spp: ESP_SPP_DATA_IND_EVT length:1 I (17416) spp: 0x3ffcfdc0 5e |^| I (17426) spp: ESP_SPP_DATA_IND_EVT length:1 I (17436) spp: 0x3ffcfddc 4a |J| W (18226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 I (18266) spp: ESP_SPP_DATA_IND_EVT length:1 I (18266) spp: 0x3ffcfda4 30 |0| I (18266) spp: ESP_SPP_DATA_IND_EVT length:1 I (18276) spp: 0x3ffcfdc0 31 |1| I (18286) spp: ESP_SPP_DATA_IND_EVT length:1 I (18286) spp: 0x3ffcfddc 32 |2| I (18296) spp: ESP_SPP_DATA_IND_EVT length:1 I (18296) spp: 0x3ffcfdf8 33 |3| I (18306) spp: ESP_SPP_DATA_IND_EVT length:1 I (18316) spp: 0x3ffcfe9c 34 |4| I (18326) spp: ESP_SPP_DATA_IND_EVT length:1 I (18326) spp: 0x3ffcfeb8 35 |5| I (18336) spp: ESP_SPP_DATA_IND_EVT length:1 I (18336) spp: 0x3ffcff7c 36 |6| I (18346) spp: ESP_SPP_DATA_IND_EVT length:1 I (18356) spp: 0x3ffcff98 37 |7| I (18356) spp: ESP_SPP_DATA_IND_EVT length:1 I (18366) spp: 0x3ffcffb4 38 |8| I (18376) spp: ESP_SPP_DATA_IND_EVT length:1 I (18376) spp: 0x3ffcffd0 39 |9| I (18416) spp: ESP_SPP_DATA_IND_EVT length:2 I (18416) spp: 0x3ffcfda4 0d 0a |..| I (18416) spp: ESP_SPP_DATA_IND_EVT length:1 I (18426) spp: 0x3ffcfdc0 5e |^| I (18436) spp: ESP_SPP_DATA_IND_EVT length:1 I (18436) spp: 0x3ffcfddc 4a |J| W (19226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 I (19266) spp: ESP_SPP_DATA_IND_EVT length:1 I (19266) spp: 0x3ffcfda4 30 |0| I (19266) spp: ESP_SPP_DATA_IND_EVT length:1 I (19266) spp: 0x3ffcfdf0 31 |1| I (19276) spp: ESP_SPP_DATA_IND_EVT length:1 I (19286) spp: 0x3ffcfe0c 32 |2| I (19296) spp: ESP_SPP_DATA_IND_EVT length:1 I (19296) spp: 0x3ffcfdc0 33 |3| I (19306) spp: ESP_SPP_DATA_IND_EVT length:1 I (19306) spp: 0x3ffcfe9c 34 |4| I (19316) spp: ESP_SPP_DATA_IND_EVT length:1 I (19326) spp: 0x3ffcfeb8 35 |5| I (19326) spp: ESP_SPP_DATA_IND_EVT length:1 I (19336) spp: 0x3ffcff7c 36 |6| I (19346) spp: ESP_SPP_DATA_IND_EVT length:1 I (19346) spp: 0x3ffcff98 37 |7| I (19356) spp: ESP_SPP_DATA_IND_EVT length:1 I (19366) spp: 0x3ffcffb4 38 |8| I (19366) spp: ESP_SPP_DATA_IND_EVT length:1 I (19376) spp: 0x3ffcffd0 39 |9| I (19426) spp: ESP_SPP_DATA_IND_EVT length:2 I (19426) spp: 0x3ffcfda4 0d 0a |..| I (19426) spp: ESP_SPP_DATA_IND_EVT length:1 I (19426) spp: 0x3ffcfdc0 5e |^| I (19436) spp: ESP_SPP_DATA_IND_EVT length:1 I (19446) spp: 0x3ffcfddc 4a |J| W (20226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 I (20266) spp: ESP_SPP_DATA_IND_EVT length:1 I (20266) spp: 0x3ffcfda4 30 |0| I (20266) spp: ESP_SPP_DATA_IND_EVT length:1 I (20266) spp: 0x3ffcfdc0 31 |1| I (20276) spp: ESP_SPP_DATA_IND_EVT length:1 I (20286) spp: 0x3ffcfddc 32 |2| I (20296) spp: ESP_SPP_DATA_IND_EVT length:1 I (20296) spp: 0x3ffcfdf8 33 |3| I (20306) spp: ESP_SPP_DATA_IND_EVT length:1 I (20306) spp: 0x3ffcfe9c 34 |4| I (20316) spp: ESP_SPP_DATA_IND_EVT length:1 I (20326) spp: 0x3ffcfeb8 35 |5| I (20326) spp: ESP_SPP_DATA_IND_EVT length:1 I (20336) spp: 0x3ffcff7c 36 |6| I (20346) spp: ESP_SPP_DATA_IND_EVT length:1 I (20346) spp: 0x3ffcff98 37 |7| I (20356) spp: ESP_SPP_DATA_IND_EVT length:1 I (20366) spp: 0x3ffcffb4 38 |8| I (20366) spp: ESP_SPP_DATA_IND_EVT length:1 I (20376) spp: 0x3ffcffd0 39 |9| I (20426) spp: ESP_SPP_DATA_IND_EVT length:2 I (20426) spp: 0x3ffcfda4 0d 0a |..| I (20426) spp: ESP_SPP_DATA_IND_EVT length:1 I (20436) spp: 0x3ffcfdc0 5e |^| I (20436) spp: ESP_SPP_DATA_IND_EVT length:1 I (20446) spp: 0x3ffcfdec 4a |J| W (21226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 I (21266) spp: ESP_SPP_DATA_IND_EVT length:1 I (21276) spp: 0x3ffcfda4 30 |0| I (21276) spp: ESP_SPP_DATA_IND_EVT length:1 I (21276) spp: 0x3ffcfdc0 31 |1| I (21286) spp: ESP_SPP_DATA_IND_EVT length:1 I (21286) spp: 0x3ffcfddc 32 |2| I (21296) spp: ESP_SPP_DATA_IND_EVT length:1 I (21306) spp: 0x3ffcfdf8 33 |3| I (21316) spp: ESP_SPP_DATA_IND_EVT length:1 I (21316) spp: 0x3ffcfe9c 34 |4| I (21326) spp: ESP_SPP_DATA_IND_EVT length:1 I (21326) spp: 0x3ffcfeb8 35 |5| I (21336) spp: ESP_SPP_DATA_IND_EVT length:1 I (21346) spp: 0x3ffcff7c 36 |6| I (21356) spp: ESP_SPP_DATA_IND_EVT length:1 I (21356) spp: 0x3ffcff98 37 |7| I (21366) spp: ESP_SPP_DATA_IND_EVT length:1 I (21366) spp: 0x3ffcffb4 38 |8| I (21376) spp: ESP_SPP_DATA_IND_EVT length:1 I (21386) spp: 0x3ffcffd0 39 |9| I (21436) spp: ESP_SPP_DATA_IND_EVT length:2 I (21436) spp: 0x3ffcfda4 0d 0a |..| I (21436) spp: ESP_SPP_DATA_IND_EVT length:1 I (21436) spp: 0x3ffcfdc0 5e |^| I (21446) spp: ESP_SPP_DATA_IND_EVT length:1 I (21456) spp: 0x3ffcfddc 4a |J| W (22226) spp: ESP_SPP_WRITE_EVT status:0 cong:0 len:12 I (22256) spp: ESP_SPP_DATA_IND_EVT length:1 I (22256) spp: 0x3ffcfda4 30 |0| I (22256) spp: ESP_SPP_DATA_IND_EVT length:1 I (22266) spp: 0x3ffcfdc0 31 |1| I (22266) spp: ESP_SPP_DATA_IND_EVT length:1 I (22276) spp: 0x3ffcfddc 32 |2| I (22286) spp: ESP_SPP_DATA_IND_EVT length:1 I (22286) spp: 0x3ffcfdf8 33 |3| I (22296) spp: ESP_SPP_DATA_IND_EVT length:1 I (22296) spp: 0x3ffcfe9c 34 |4| I (22306) spp: ESP_SPP_DATA_IND_EVT length:1 I (22316) spp: 0x3ffcfeb8 35 |5| I (22326) spp: ESP_SPP_DATA_IND_EVT length:1 I (22326) spp: 0x3ffcff7c 36 |6| I (22336) spp: ESP_SPP_DATA_IND_EVT length:1 I (22336) spp: 0x3ffcff98 37 |7| I (22346) spp: ESP_SPP_DATA_IND_EVT length:1 I (22356) spp: 0x3ffcffb4 38 |8| I (22366) spp: ESP_SPP_DATA_IND_EVT length:1 I (22366) spp: 0x3ffcffd0 39 |9| I (22406) spp: ESP_SPP_DATA_IND_EVT length:2 I (22406) spp: 0x3ffcfda4 0d 0a |..| I (22406) spp: ESP_SPP_DATA_IND_EVT length:1 I (22416) spp: 0x3ffcfdc0 5e |^| I (22416) spp: ESP_SPP_DATA_IND_EVT length:1 I (22426) spp: 0x3ffcfddc 4a |J| ```
boblane1 commented 9 months ago

@LaXiS96 I reproduce the issue in the following steps:

  1. Use sudo rfcomm connect /dev/rfcomm0 xx:xx:xx:xx:xx:xx, the connection will be established, and the terminal client will loopback the received data
  2. Open the cutecom and open the port /dev/rfcomm0, then the data will dispatch to the cutecom
  3. Close the cutecom, the terminal client will loopback the received data again

I think this issue is caused by rfcomm connect command. Try to use sudo rfcomm bind /dev/rfcomm0 xx:xx:xx:xx:xx:xx, open and close the /dev/rfcomm0 in cutecom, then you will receive the ESP_SPP_SRV_OPEN_EVT and ESP_SPP_CLOSE_EVT in ESP32.

LaXiS96 commented 9 months ago

Huh, that was exactly it! I was using the blueman GUI to connect to the ESP32, and it looks like it does connect instead of bind. I'll use the rfcomm CLI from now on; I don't understand why the connect implementation loops back data but I guess that's not a problem anymore. Thank you for your help @boblane1