Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Two classic BT HID devices connecting at the same time fail with ERR_SDP (BT_SDP: process_service_attr_rsp occurs after ESP_HIDH_OPEN_EVENT). (IDFGH-9100) #10504

Closed
3 tasks done
benryves opened this issue Jan 7, 2023 · 13 comments
Assignees
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally Type: Bug bugs in IDF

Comments

@benryves
Copy link

benryves commented Jan 7, 2023

Answers checklist.

  • I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
  • I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
  • I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v5.0

Operating System used.

Windows

How did you build your project?

VS Code IDE

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

PowerShell

Development Kit.

DOIT ESP32 DEVKIT V1

Power Supply used.

USB

What is the expected behavior?

I am attempting to connect two Wii remotes (which are classic Bluetooth HID devices) to an ESP32. The Wii remotes have previously been successfully paired individually (after searching for them and sending the appropriate PIN using the BT GAP API before using the HIDH API to open the device).

If the ESP32 is reset the Wii remotes will reconnect to it automatically, with no need to search for them again via GAP API or by using the HIDH API to open the device. If only one Wii remote is switched on at a time, then both connect successfully. Ideally this should also happen if both Wii remotes are switched on at the same time.

What is the actual behavior?

If both Wii remotes are switched on at the same time then they will both fail to connect with ERR_SDP. If a Wii remote is then switched off (resulting in bta_hh_co_close being called) then BT_HIDH generates a Device Not Found and CLOSE ERROR: NO_CONNECTION and the ESP32 crashes and reboots.

The only thing I can see that indicates what the issue might be is that when the Wii remotes connect successfully the log shows two events from BT_SDP: process_service_attr_rsp before the HIDH open callback is invoked. When the connections fail these BT_SDP: process_service_attr_rsp events come after the HIDH open callback.

Steps to reproduce.

  1. Pair two Wii remotes to an ESP32.
  2. Reset the ESP32 with both Wii remotes connected, OR reset the ESP32 and switch on both Wii remotes by pressing a button on them simultaneously.
  3. If the two Wii remotes try to reconnect at the same time, neither will properly reconnect. (If they stagger the times that they try to reconnect then all is fine).

Debug Logs.

********** Successful connection: **********

W (7000) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
E (8150) BT_BTM: tBTM_SEC_DEV:0x3ffd18d4 rs_disc_pending=0
W (8400) BT_SDP: process_service_attr_rsp
W (8710) BT_SDP: process_service_attr_rsp
W (8720) BT_APPL: new conn_srvc id:23, app_id:5
I (8740) BT: HIDH open 00:21:bd:07:b6:41: 
BDA:00:21:bd:07:b6:41, Status: OK, Connected: YES, Handle: 0, Usage: GAMEPAD
Name: , Manufacturer: , Serial Number:
PID: 0x0306, VID: 0x057e, VERSION: 0x0600
Report Map Length: 217
    VENDOR   INPUT REPORT, ID:  63, Length:  21
    VENDOR   INPUT REPORT, ID:  62, Length:  21
    VENDOR   INPUT REPORT, ID:  61, Length:  21
    VENDOR   INPUT REPORT, ID:  55, Length:  21
    VENDOR   INPUT REPORT, ID:  54, Length:  21
    VENDOR   INPUT REPORT, ID:  53, Length:  21
    VENDOR   INPUT REPORT, ID:  52, Length:  21
    VENDOR   INPUT REPORT, ID:  51, Length:  17
    VENDOR   INPUT REPORT, ID:  50, Length:  10
    VENDOR   INPUT REPORT, ID:  49, Length:   5
    VENDOR   INPUT REPORT, ID:  48, Length:   2
    VENDOR   INPUT REPORT, ID:  34, Length:   4
    VENDOR   INPUT REPORT, ID:  33, Length:  21
    VENDOR   INPUT REPORT, ID:  32, Length:   6
    VENDOR  OUTPUT REPORT, ID:  26, Length:   1
    VENDOR  OUTPUT REPORT, ID:  25, Length:   1
    VENDOR  OUTPUT REPORT, ID:  24, Length:  21
    VENDOR  OUTPUT REPORT, ID:  23, Length:   6
    VENDOR  OUTPUT REPORT, ID:  22, Length:  21
    VENDOR  OUTPUT REPORT, ID:  21, Length:   1
    VENDOR  OUTPUT REPORT, ID:  20, Length:   1
    VENDOR  OUTPUT REPORT, ID:  19, Length:   1
    VENDOR  OUTPUT REPORT, ID:  18, Length:   2
    VENDOR  OUTPUT REPORT, ID:  17, Length:   1
   GAMEPAD  OUTPUT REPORT, ID:  16, Length:   1
I (8850) MAIN: Assigning slot 0

********** Failed connection: **********

W (5730) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
W (6670) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
E (6880) BT_BTM: tBTM_SEC_DEV:0x3ffd18d4 rs_disc_pending=0
E (7090) BT_HIDH: OPEN ERROR: ERR_SDP
E (7090) BT: HIDH open failed (-1)
W (7100) BT_HIDH: HID-Host Rcvd L2CAP disc cfm, unknown CID: 0x44
W (7160) BT_SDP: process_service_attr_rsp
W (7480) BT_SDP: process_service_attr_rsp

********** Crash after failed connection: **********

W (93351) BT_APPL: bta_hh_co_close: dev_handle = 1, app_id = 5
W (93351) BT_APPL: bta_dm_act no entry for connected service cbs
E (93361) BT_BTC: Error: cannot find device with handle 1
E (93361) BT_HIDH: Device Not Found
E (93371) BT_HIDH: CLOSE ERROR: NO_CONNECTION
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.

Core  1 register dump:
PC      : 0x400db050  PS      : 0x00060130  A0      : 0x8014991c  A1      : 0x3ffd3d30  
0x400db050: hidh_callback at D:/Documents/Documents/GitHub/LightGunCommando/hosts/wii_remote/firmware/main/bt.c:217

A2      : 0x00000000  A3      : 0x3f405718  A4      : 0x00000004  A5      : 0x3ffd7894
A6      : 0x000000fd  A7      : 0x0000abab  A8      : 0x800db04e  A9      : 0x3ffd3d10
A10     : 0x00016cbb  A11     : 0x00000000  A12     : 0x00000000  A13     : 0xff000000
A14     : 0x00000004  A15     : 0x0000abab  SAR     : 0x00000018  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x00000000  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0x00000000  


Backtrace: 0x400db04d:0x3ffd3d30 0x40149919:0x3ffd3d90 0x401494b6:0x3ffd3dc0 0x4014958d:0x3ffd3e00 0x4009503d:0x3ffd3e20
0x400db04d: hidh_callback at D:/Documents/Documents/GitHub/LightGunCommando/hosts/wii_remote/firmware/main/bt.c:217

0x40149919: handler_execute at D:/Documents/Documents/Electronics/ESP/esp-idf/components/esp_event/esp_event.c:137

0x401494b6: esp_event_loop_run at D:/Documents/Documents/Electronics/ESP/esp-idf/components/esp_event/esp_event.c:582 (discriminator 3)

0x4014958d: esp_event_loop_run_task at D:/Documents/Documents/Electronics/ESP/esp-idf/components/esp_event/esp_event.c:107 (discriminator 15)

0x4009503d: vPortTaskWrapper at D:/Documents/Documents/Electronics/ESP/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:151





ELF file SHA256: e127f984b20ef496

Rebooting...

More Information.

No response

@benryves benryves added the Type: Bug bugs in IDF label Jan 7, 2023
@github-actions github-actions bot changed the title Two classic BT HID devices connecting at the same time fail with ERR_SDP (BT_SDP: process_service_attr_rsp occurs after ESP_HIDH_OPEN_EVENT). Two classic BT HID devices connecting at the same time fail with ERR_SDP (BT_SDP: process_service_attr_rsp occurs after ESP_HIDH_OPEN_EVENT). (IDFGH-9100) Jan 7, 2023
@espressif-bot espressif-bot added the Status: Opened Issue is new label Jan 7, 2023
@boblane1
Copy link
Collaborator

boblane1 commented Jan 9, 2023

Hi @benryves,

Thanks for reporting!

Reset the ESP32 with both Wii remotes connected, OR reset the ESP32 and switch on both Wii remotes by pressing a button on them simultaneously.

Do the two procedures have the same result(ERR_SDP)? And can you always reproduce the issue? I can't reproduce the issue as you described. So please help enable the following config:

Component config > Bluetooth > Bluedroid Options > BT DEBUG LOG LEVEL > L2CAP layer -> Event
Component config > Bluetooth > Bluedroid Options > BT DEBUG LOG LEVEL > APPL layer -> Debug
Component config > Log output > Default log verbosity -> Debug

The crash may be caused by referring to the NULL pointer in the hidh_callback function, please check the pointer before using it.

@benryves
Copy link
Author

benryves commented Jan 9, 2023

Thank you for your reply, @boblane1!

Both procedures have the same ERR_SDP error. Having both remotes connected and then resetting the ESP32 is the easier way to trigger the issue as it is more likely that they try to connect at the same time, but it is also possible to trigger the error manually by switching on the Wii remotes at the same time. Staggering their

I don't really understand what's going on internally but what stands out to me is when the Wii remotes connect successfully I get a message from BT_SDP: process_service_attr_rsp before BT_HIDH opens the device. When I switch them on at the same time the BT_SDP: process_service_attr_rsp comes after the BT_HIDH failure. I tried to dig my way into the code to see why these would appear to happen out of order but it's all a bit beyond me, sorry!

I changed the configuration options as requested, here is the log of a failed connection:

D (1612) BT_APPL: Enable HCI

D (1622) nvs: nvs_open_from_partition bt_config.conf 1
D (1622) nvs: nvs_get_str_or_blob bt_cfg_key0
D (1622) nvs: nvs_get_str_or_blob bt_cfg_key0
D (1632) nvs: nvs_close 2
D (1632) nvs: nvs_open_from_partition bt_config.conf 1
D (1632) nvs: nvs_set_blob bt_cfg_key0 1467
D (1642) nvs: nvs_close 3
D (1642) BT_APPL: BTA got event 0x100

D (1642) BT_APPL: bta_dm_sm_execute event:0x0
D (1642) BT_APPL: BTA got event 0x0

D (1652) BT_APPL: bta_sys_sm_execute state:0, event:0x0

D (1652) BT_APPL: bta_sys_hw_api_enable for 0, active modules 0x0001

D (1662) BT_APPL: BTA got event 0x1

D (1662) BT_APPL: bta_sys_sm_execute state:1, event:0x1

D (1672) BT_APPL: bta_sys_hw_evt_enabled for 0

D (1712) BT_APPL:  bta_sys_hw_btm_cback was called with parameter: 0
D (1712) BT_APPL: BTA got event 0x2

D (1722) BT_APPL: bta_sys_sm_execute state:1, event:0x2

D (1722) BT_APPL:  bta_sys_hw_evt_stack_enabled!notify the callers

D (1722) BT_APPL: bta_dm_sys_hw_cback with event: 1
D (1732) BT_APPL: bta_sys_free_timer expected alarm was not in bta alarm hash map.
D (1752) BT_APPL: BTA got event 0x108

D (1752) BT_APPL: bta_dm_sm_execute event:0x8
D (1752) BT_APPL: BTA got event 0x108

D (1752) BT_APPL: bta_dm_sm_execute event:0x8
D (1762) BT_APPL: BTA got event 0x102

D (1762) BT_APPL: bta_dm_sm_execute event:0x2
D (1772) BT_APPL: BTA is generating EIR
D (1772) event: created task for loop 0x3ffd1b2c
D (1772) event: created event loop 0x3ffd1b2c
D (1772) event: running task for loop 0x3ffd1b2c
I (1782) BT_APPL: BTA_HhEnable sec_mask:0x36 p_cback:0x400e11b8
0x400e11b8: bte_hh_evt at D:/Documents/Documents/Electronics/ESP/esp-idf/components/bt/host/bluedroid/btc/profile/std/hid/btc_hh.c:374

D (1792) BT_APPL: BTA got event 0x170c

D (1792) event: runningD (1792) intr_alloc: Connected src 22 to int 13 (cpu 0)
 post ESP_HIDH_EVENTS:5 with handler 0x400dd210 and context 0x3ffd1c14 on loop 0x3ffd1b2c
0x400dd210: esp_hidh_process_event_data_handler at D:/Documents/Documents/Electronics/ESP/esp-idf/components/esp_hid/src/esp_hidh.c:812

D (1792) BT_APPL: BTA got event 0x10c

D (1812) event: running post ESP_HIDH_EVENTS:5 with handler 0x400dc5b8 and context 0x3ffd1c34 on loop 0x3ffd1b2c
0x400dc5b8: hidh_callback at D:/Documents/Documents/GitHub/LightGunCommando/hosts/wii_remote/firmware/main/bt.c:177

I (1822) BT: HIDH stack started
D (1822) BT_APPL: bta_dm_sm_execute event:0xc
D (1832) BT_APPL: BTA got event 0x106

D (1832) BT_APPL: bta_dm_sm_execute event:0x6
D (5132) BT_L2CAP: l2c_link_adjust_allocation  num_hipri: 0  num_lowpri: 1  low_quota: 9  round_robin_quota: 0  qq: 9

D (5132) BT_L2CAP: l2c_link_adjust_allocation   Priority: 0  XmitQuota: 9

D (5142) BT_L2CAP:         SentNotAcked: 0  RRUnacked: 0

D (5192) BT_L2CAP: l2cu_send_peer_info_req: type 0x0002
W (5192) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
D (5202) BT_APPL: BTA got event 0x107

D (5202) BT_APPL: bta_dm_sm_execute event:0x7
D (5202) BT_APPL: BTA got event 0x107

D (5202) BT_APPL: bta_dm_sm_execute event:0x7
D (5202) BT_APPL: bta_dm_acl_change info: 0x0
I (5212) BT_L2CAP: L2CA_SetDesireRole() new:x1, disallow_switch:0
D (5892) BT_L2CAP: l2c_link_adjust_allocation  num_hipri: 0  num_lowpri: 2  low_quota: 9  round_robin_quota: 0  qq: 4

D (5892) BT_L2CAP: l2c_link_adjust_allocation   Priority: 0  XmitQuota: 5

D (5902) BT_L2CAP:         SentNotAcked: 0  RRUnacked: 0

D (5902) BT_L2CAP: l2c_link_adjust_allocation   Priority: 0  XmitQuota: 4

D (5912) BT_L2CAP:         SentNotAcked: 0  RRUnacked: 0

D (6202) BT_L2CAP: l2cu_send_peer_info_req: type 0x0002
W (6212) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
D (6212) BT_APPL: BTA got event 0x107

D (6212) BT_APPL: bta_dm_sm_execute event:0x7
D (6212) BT_APPL: BTA got event 0x107

D (6222) BT_APPL: bta_dm_sm_execute event:0x7
D (6222) BT_APPL: bta_dm_acl_change info: 0x0
I (6232) BT_L2CAP: L2CA_SetDesireRole() new:x1, disallow_switch:0
D (6282) BT_L2CAP: CID:0x0040 FCR Mode:0 Priority:2 TxDataRate:1 RxDataRate:1 Quota:20
D (6282) BT_L2CAP: L2CAP - st: CLOSED evt: 10
D (6282) BT_L2CAP: L2CAP - st: TERM_W4_SEC_COMP evt: 7
I (6292) BT_L2CAP: L2CAP - Calling Connect_Ind_Cb(), CID: 0x0040
I (6292) BT_L2CAP: L2CA_ErtmConnectRsp()  CID: 0x0040  Result: 1  Status: 0  BDA: 0022d76a4bbc  p_ertm_info:0x0
D (6302) BT_L2CAP: L2CAP - st: W4_L2CA_CON_RSP evt: 22
E (6342) BT_BTM: tBTM_SEC_DEV:0x3ffd1950 rs_disc_pending=0

D (6342) BT_APPL: BTA got event 0x107

D (6342) BT_APPL: bta_dm_sm_execute event:0x7
D (6342) BT_APPL: bta_dm_acl_change role chg info:x0 new_role:0 dev count:2
D (6352) BT_APPL: bta_dm_check_av:0
D (6352) BT_L2CAP: CID:0x0040 FCR Mode:0 Priority:2 TxDataRate:1 RxDataRate:1 Quota:20
D (6362) BT_L2CAP: L2CAP - st: CLOSED evt: 10
D (6362) BT_L2CAP: L2CAP - st: TERM_W4_SEC_COMP evt: 7
I (6372) BT_L2CAP: L2CAP - Calling Connect_Ind_Cb(), CID: 0x0041
I (6382) BT_L2CAP: L2CA_ErtmConnectRsp()  CID: 0x0041  Result: 1  Status: 0  BDA: 0021bd07b641  p_ertm_info:0x0
D (6392) BT_L2CAP: L2CAP - st: W4_L2CA_CON_RSP evt: 22
I (6472) BT_L2CAP: L2CA_ErtmConnectRsp()  CID: 0x0040  Result: 0  Status: 0  BDA: 0022d76a4bbc  p_ertm_info:0x0
D (6472) BT_L2CAP: L2CAP - st: W4_L2CA_CON_RSP evt: 22
I (6472) BT_L2CAP: L2CA_ConfigReq()  CID 0x0040: fcr_present:0 (mode 0) mtu_present:1 (640)
D (6482) BT_L2CAP: L2CAP - st: CONFIG evt: 24
D (6492) BT_L2CAP: L2CAP - st: CONFIG evt: 14
D (6492) BT_L2CAP: l2c_fcr_process_peer_cfg_req() CFG fcr_present:0 fcr.mode:0 CCB FCR mode:0 preferred: 0 allowed:9
D (6502) BT_L2CAP: L2CAP - Calling Config_Req_Cb(), CID: 0x0040, C-bit 0
I (6512) BT_L2CAP: L2CA_ConfigRsp()  CID: 0x0040  Result: 0 MTU present:0 Flush TO:0 FCR:0 FCS:0
D (6522) BT_L2CAP: L2CAP - st: CONFIG evt: 25
I (6522) BT_L2CAP: L2CA_ErtmConnectRsp()  CID: 0x0041  Result: 0  Status: 0  BDA: 0021bd07b641  p_ertm_info:0x0
D (6532) BT_L2CAP: L2CAP - st: W4_L2CA_CON_RSP evt: 22
I (6542) BT_L2CAP: L2CA_ConfigReq()  CID 0x0041: fcr_present:0 (mode 0) mtu_present:1 (640)
D (6552) BT_L2CAP: L2CAP - st: CONFIG evt: 24
D (6552) BT_L2CAP: L2CAP - st: CONFIG evt: 15
D (6562) BT_L2CAP: CID:0x0040 FCR Mode:0 Priority:2 TxDataRate:1 RxDataRate:1 Quota:20
I (6562) BT_L2CAP: L2CAP - Calling Config_Rsp_Cb(), CID: 0x0040
D (6572) BT_L2CAP: CID:0x0040 FCR Mode:0 Priority:2 TxDataRate:1 RxDataRate:1 Quota:20
D (6582) BT_L2CAP: L2CAP - st: CLOSED evt: 10
D (6582) BT_L2CAP: L2CAP - st: TERM_W4_SEC_COMP evt: 7
I (6592) BT_L2CAP: L2CAP - Calling Connect_Ind_Cb(), CID: 0x0042
I (6602) BT_L2CAP: L2CA_ErtmConnectRsp()  CID: 0x0042  Result: 0  Status: 0  BDA: 0022d76a4bbc  p_ertm_info:0x0
D (6612) BT_L2CAP: L2CAP - st: W4_L2CA_CON_RSP evt: 22
I (6612) BT_L2CAP: L2CA_ConfigReq()  CID 0x0042: fcr_present:0 (mode 0) mtu_present:1 (640)
D (6622) BT_L2CAP: L2CAP - st: CONFIG evt: 24
D (6632) BT_L2CAP: L2CAP - st: CONFIG evt: 14
D (6632) BT_L2CAP: l2c_fcr_process_peer_cfg_req() CFG fcr_present:0 fcr.mode:0 CCB FCR mode:0 preferred: 0 allowed:9
D (6642) BT_L2CAP: L2CAP - Calling Config_Req_Cb(), CID: 0x0041, C-bit 0
I (6652) BT_L2CAP: L2CA_ConfigRsp()  CID: 0x0041  Result: 0 MTU present:0 Flush TO:0 FCR:0 FCS:0
D (6662) BT_L2CAP: L2CAP - st: CONFIG evt: 25
D (6662) BT_L2CAP: L2CAP - st: CONFIG evt: 15
D (6672) BT_L2CAP: CID:0x0040 FCR Mode:0 Priority:2 TxDataRate:1 RxDataRate:1 Quota:20
I (6672) BT_L2CAP: L2CAP - Calling Config_Rsp_Cb(), CID: 0x0041
D (6682) BT_L2CAP: L2CAP - st: CONFIG evt: 14
D (6682) BT_L2CAP: l2c_fcr_process_peer_cfg_req() CFG fcr_present:0 fcr.mode:0 CCB FCR mode:0 preferred: 0 allowed:9
D (6692) BT_L2CAP: L2CAP - Calling Config_Req_Cb(), CID: 0x0042, C-bit 0
I (6702) BT_L2CAP: L2CA_ConfigRsp()  CID: 0x0042  Result: 0 MTU present:0 Flush TO:0 FCR:0 FCS:0
D (6712) BT_L2CAP: L2CAP - st: CONFIG evt: 25
D (6722) BT_L2CAP: L2CAP - st: CONFIG evt: 15
D (6722) BT_L2CAP: CID:0x0040 FCR Mode:0 Priority:2 TxDataRate:1 RxDataRate:1 Quota:20
I (6732) BT_L2CAP: L2CAP - Calling Config_Rsp_Cb(), CID: 0x0042
D (6732) BT_APPL: bta_hh_cback::HID_event [HID_HDEV_EVT_OPEN]
D (6742) BT_L2CAP: CID:0x0040 FCR Mode:0 Priority:2 TxDataRate:1 RxDataRate:1 Quota:20
D (6752) BT_L2CAP: L2CAP - st: CLOSED evt: 10
D (6752) BT_L2CAP: L2CAP - st: TERM_W4_SEC_COMP evt: 7
I (6762) BT_L2CAP: L2CAP - Calling Connect_Ind_Cb(), CID: 0x0043
I (6762) BT_L2CAP: L2CA_ErtmConnectRsp()  CID: 0x0043  Result: 0  Status: 0  BDA: 0021bd07b641  p_ertm_info:0x0
D (6782) BT_L2CAP: L2CAP - st: W4_L2CA_CON_RSP evt: 22
I (6782) BT_L2CAP: L2CA_ConfigReq()  CID 0x0043: fcr_present:0 (mode 0) mtu_present:1 (640)
D (6792) BT_L2CAP: L2CAP - st: CONFIG evt: 24
D (6802) BT_L2CAP: L2CAP - st: OPEN evt: 20
D (6802) BT_APPL: bta_hh_cback::HID_event [HID_HDEV_EVT_INTR_DATA]
D (6802) BT_APPL: BTA got event 0x1702

D (6812) BT_APPL: in_use ? [0] kdev[0].hid_handle = 255 state = [1]
D (6812) BT_APPL: in_use ? [0] kdev[1].hid_handle = 255 state = [1]
D (6822) BT_APPL: in_use ? [0] kdev[2].hid_handle = 255 state = [1]
D (6832) BT_APPL: in_use ? [0] kdev[3].hid_handle = 255 state = [1]
D (6832) BT_APPL: in_use ? [0] kdev[4].hid_handle = 255 state = [1]
D (6842) BT_APPL: in_use ? [0] kdev[5].hid_handle = 255 state = [1]
D (6852) BT_APPL: in_use ? [0] kdev[6].hid_handle = 255 state = [1]
D (6852) BT_APPL: bta_hh_find_cb:: index = 0 while max = 7
D (6862) BT_APPL: bta_hh_hdl_event:: handle = 0 dev_cb[0]
D (6862) BT_APPL: bta_hh_sm_execute: State 0x01 [BTA_HH_IDLE_ST], Event [BTA_HH_INT_OPEN_EVT]
D (6872) BT_APPL: bta_hh_open_act:  Device[0] connected
I (6882) BT_L2CAP: L2CA_ErtmConnectReq()  PSM: 0x0001  BDA: 0022d76a4bbc  p_ertm_info: 0x0 allowed:0x0 preferred:0
D (6892) BT_L2CAP: CID:0x0040 FCR Mode:0 Priority:2 TxDataRate:1 RxDataRate:1 Quota:20
D (6902) BT_L2CAP: L2CAP - st: CLOSED evt: 21
D (6902) BT_L2CAP: L2CAP - st: CLOSED evt: 7
I (6912) BT_L2CAP: L2CAP - L2CA_conn_req(psm: 0x0001) returned CID: 0x0044
D (6912) BT_APPL: HH State Change: [BTA_HH_IDLE_ST] -> [BTA_HH_W4_CONN_ST] after Event [BTA_HH_INT_OPEN_EVT]
D (6922) BT_L2CAP: L2CAP - st: CONFIG evt: 14
D (6932) BT_L2CAP: l2c_fcr_process_peer_cfg_req() CFG fcr_present:0 fcr.mode:0 CCB FCR mode:0 preferred: 0 allowed:9
D (6942) BT_L2CAP: L2CAP - Calling Config_Req_Cb(), CID: 0x0043, C-bit 0
I (6942) BT_L2CAP: L2CA_ConfigRsp()  CID: 0x0043  Result: 0 MTU present:0 Flush TO:0 FCR:0 FCS:0
D (6952) BT_L2CAP: L2CAP - st: CONFIG evt: 25
D (6962) BT_APPL: BTA got event 0x1704

D (6962) BT_APPL: bta_hh_hdl_event:: handle = 0 dev_cb[0] 
D (6972) BT_APPL: bta_hh_sm_execute: State 0x02 [BTA_HH_W4_CONN_ST], Event [BTA_HH_INT_DATA_EVT]
D (6982) BT_L2CAP: L2CAP - st: CONFIG evt: 15
D (6982) BT_L2CAP: CID:0x0040 FCR Mode:0 Priority:2 TxDataRate:1 RxDataRate:1 Quota:20
I (6992) BT_L2CAP: L2CAP - Calling Config_Rsp_Cb(), CID: 0x0043
D (7002) BT_APPL: bta_hh_cback::HID_event [HID_HDEV_EVT_OPEN]
D (7002) BT_L2CAP: L2CAP - st: W4_L2CAP_CON_RSP evt: 11
I (7012) BT_L2CAP: L2CAP - Calling Connect_Cfm_Cb(), CID: 0x0044, Success
I (7012) BT_L2CAP: L2CA_ConfigReq()  CID 0x0044: fcr_present:0 (mode 0) mtu_present:1 (672)
D (7022) BT_L2CAP: L2CAP - st: CONFIG evt: 24
D (7032) BT_L2CAP: L2CAP - st: OPEN evt: 20
D (7032) BT_APPL: bta_hh_cback::HID_event [HID_HDEV_EVT_INTR_DATA]
D (7042) BT_APPL: BTA got event 0x1702

D (7042) BT_APPL: in_use ? [0] kdev[0].hid_handle = 255 state = [2]
D (7052) BT_APPL: in_use ? [0] kdev[1].hid_handle = 255 state = [1]
D (7062) BT_APPL: in_use ? [0] kdev[2].hid_handle = 255 state = [1]
D (7062) BT_APPL: in_use ? [0] kdev[3].hid_handle = 255 state = [1]
D (7072) BT_APPL: in_use ? [0] kdev[4].hid_handle = 255 state = [1]
D (7072) BT_APPL: in_use ? [0] kdev[5].hid_handle = 255 state = [1]
D (7082) BT_APPL: in_use ? [0] kdev[6].hid_handle = 255 state = [1]
D (7092) BT_APPL: bta_hh_find_cb:: index = 0 while max = 7
D (7092) BT_APPL: bta_hh_hdl_event:: handle = 1 dev_cb[0]
D (7102) BT_APPL: bta_hh_sm_execute: State 0x02 [BTA_HH_W4_CONN_ST], Event [BTA_HH_INT_OPEN_EVT]
D (7112) BT_APPL: bta_hh_open_act:  Device[1] connected
D (7112) BT_APPL: bta_hh_sm_execute: State 0x02 [BTA_HH_W4_CONN_ST], Event [BTA_HH_SDP_CMPL_EVT]
D (7122) BT_APPL: bta_hh_sdp_cmpl:  status 0x 7
D (7132) BT_APPL: bta_hh_sdp_cmpl:SDP failed for  incoming conn :hndl 1
I (7132) BT_L2CAP: L2CA_DisconnectReq()  CID: 0x0043
D (7142) BT_L2CAP: L2CAP - st: OPEN evt: 27
D (7142) BT_APPL: bta_hh_sm_execute: State 0x02 [BTA_HH_W4_CONN_ST], Event [BTA_HH_API_CLOSE_EVT]
D (7152) BT_APPL: HH State Change: [BTA_HH_W4_CONN_ST] -> [BTA_HH_IDLE_ST] after Event [BTA_HH_API_CLOSE_EVT]
D (7162) BT_APPL: bta_hh_trace_dev_db:: Device DB list********************
D (7172) BT_APPL: kdev[0] in_use[0]  handle[255] 
D (7172) BT_APPL:                        attr_mask[0000] state [1] sub_class[00] index = 0
D (7182) BT_APPL: kdev[1] in_use[0]  handle[255]
D (7182) BT_APPL:                        attr_mask[0000] state [1] sub_class[00] index = 1
D (7192) BT_APPL: kdev[2] in_use[0]  handle[255]
D (7202) BT_APPL:                        attr_mask[0000] state [1] sub_class[00] index = 2
D (7202) BT_APPL: kdev[3] in_use[0]  handle[255]
D (7212) BT_APPL:                        attr_mask[0000] state [1] sub_class[00] index = 3
D (7212) BT_APPL: kdev[4] in_use[0]  handle[255]
D (7222) BT_APPL:                        attr_mask[0000] state [1] sub_class[00] index = 4
D (7232) BT_APPL: kdev[5] in_use[0]  handle[255]
D (7232) BT_APPL:                        attr_mask[0000] state [1] sub_class[00] index = 5
D (7242) BT_APPL: kdev[6] in_use[0]  handle[255]
D (7242) BT_APPL:                        attr_mask[0000] state [1] sub_class[00] index = 6
D (7252) BT_APPL: *********************************************************
D (7262) BT_APPL: HH State Change: [BTA_HH_W4_CONN_ST] -> [BTA_HH_IDLE_ST] after Event [BTA_HH_SDP_CMPL_EVT]
D (7272) BT_APPL: HH State Change: [BTA_HH_W4_CONN_ST] -> [BTA_HH_IDLE_ST] after Event [BTA_HH_INT_OPEN_EVT]
D (7282) BT_APPL: BTA got event 0x1704

D (7282) BT_APPL: bta_hh_hdl_event:: handle = 1 dev_cb[0] 
D (7282) BT_APPL: bta_hh_sm_execute: State 0x01 [BTA_HH_IDLE_ST], Event [BTA_HH_INT_DATA_EVT]
D (7292) BT_L2CAP: L2CAP - st: CONFIG evt: 15
I (7302) BT_L2CAP: L2CAP - Calling Config_Rsp_Cb(), CID: 0x0044
D (7302) BT_L2CAP: L2CAP - st: CONFIG evt: 14
D (7312) BT_L2CAP: l2c_fcr_process_peer_cfg_req() CFG fcr_present:0 fcr.mode:0 CCB FCR mode:0 preferred: 0 allowed:1
D (7322) BT_L2CAP: L2CAP - Calling Config_Req_Cb(), CID: 0x0044, C-bit 0
I (7332) BT_L2CAP: L2CA_ConfigRsp()  CID: 0x0044  Result: 0 MTU present:0 Flush TO:0 FCR:0 FCS:0
D (7342) BT_L2CAP: L2CAP - st: CONFIG evt: 25
D (7342) BT_L2CAP: CID:0x0040 FCR Mode:0 Priority:2 TxDataRate:1 RxDataRate:1 Quota:20
I (7352) BT_L2CAP: L2CA_DataWrite()  CID: 0x0044  Len: 13
D (7352) BT_L2CAP: L2CAP - st: OPEN evt: 30
D (7362) BT_L2CAP: L2CAP - st: W4_L2CAP_DISC_RSP evt: 18
D (7362) BT_L2CAP: CID:0x0040 FCR Mode:0 Priority:2 TxDataRate:1 RxDataRate:1 Quota:20
I (7372) BT_L2CAP: L2CAP - Calling DisconnectCfm_Cb(), CID: 0x0043
W (7382) BT_HIDH: HID-Host Rcvd L2CAP disc cfm, unknown CID: 0x43
D (7392) BT_APPL: bta_dm_delay_role_switch_cback: initiating Delayed RS
I (7392) BT_L2CAP: L2CA_SetDesireRole() new:x1, disallow_switch:0
D (7402) BT_APPL: bta_dm_delay_role_switch_cback: initiating Delayed RS
I (7412) BT_L2CAP: L2CA_SetDesireRole() new:x1, disallow_switch:0
D (7412) BT_L2CAP: L2CAP - st: OPEN evt: 20
I (7422) BT_L2CAP: L2CA_DataWrite()  CID: 0x0044  Len: 19
D (7422) BT_L2CAP: L2CAP - st: OPEN evt: 30
D (7432) BT_HIDH: incoming device connect
E (7432) BT_HIDH: OPEN ERROR: ERR_SDP
D (7442) event: running post ESP_HIDH_EVENTS:0 with handler 0x400dd210 and context 0x3ffd1c14 on loop 0x3ffd1b2c
0x400dd210: esp_hidh_process_event_data_handler at D:/Documents/Documents/Electronics/ESP/esp-idf/components/esp_hid/src/esp_hidh.c:812

D (7452) event: running post ESP_HIDH_EVENTS:0 with handler 0x400dc5b8 and context 0x3ffd1c34 on loop 0x3ffd1b2c
0x400dc5b8: hidh_callback at D:/Documents/Documents/GitHub/LightGunCommando/hosts/wii_remote/firmware/main/bt.c:177

E (7462) BT: HIDH open failed (-1)
D (7492) BT_L2CAP: L2CAP - st: OPEN evt: 20
W (7492) BT_SDP: process_service_attr_rsp

I (7492) BT_L2CAP: L2CA_DisconnectReq()  CID: 0x0044
D (7492) BT_L2CAP: L2CAP - st: OPEN evt: 27
D (7502) BT_L2CAP: L2CAP - st: W4_L2CAP_DISC_RSP evt: 18
D (7502) BT_L2CAP: CID:0x0040 FCR Mode:0 Priority:2 TxDataRate:1 RxDataRate:1 Quota:20
I (7512) BT_L2CAP: L2CAP - Calling DisconnectCfm_Cb(), CID: 0x0044
D (7512) BT_APPL: bta_hh_di_sdp_cback: p_cb: 0x3ffc543c result 0x00
D (7522) BT_APPL: vendor_id = 0x57e product_id = 0x306 version = 0x600
I (7532) BT_L2CAP: L2CA_ErtmConnectReq()  PSM: 0x0001  BDA: 0021bd07b641  p_ertm_info: 0x0 allowed:0x0 preferred:0
D (7542) BT_L2CAP: CID:0x0040 FCR Mode:0 Priority:2 TxDataRate:1 RxDataRate:1 Quota:20
D (7552) BT_L2CAP: L2CAP - st: CLOSED evt: 21
D (7552) BT_L2CAP: L2CAP - st: CLOSED evt: 7
I (7562) BT_L2CAP: L2CAP - L2CA_conn_req(psm: 0x0001) returned CID: 0x0044
D (7572) BT_L2CAP: L2CAP - st: W4_L2CAP_CON_RSP evt: 11
I (7572) BT_L2CAP: L2CAP - Calling Connect_Cfm_Cb(), CID: 0x0044, Success
I (7572) BT_L2CAP: L2CA_ConfigReq()  CID 0x0044: fcr_present:0 (mode 0) mtu_present:1 (672)
D (7582) BT_L2CAP: L2CAP - st: CONFIG evt: 24
D (7602) BT_L2CAP: L2CAP - st: CONFIG evt: 15
I (7602) BT_L2CAP: L2CAP - Calling Config_Rsp_Cb(), CID: 0x0044
D (7602) BT_L2CAP: L2CAP - st: CONFIG evt: 14
D (7602) BT_L2CAP: l2c_fcr_process_peer_cfg_req() CFG fcr_present:0 fcr.mode:0 CCB FCR mode:0 preferred: 0 allowed:1
D (7612) BT_L2CAP: L2CAP - Calling Config_Req_Cb(), CID: 0x0044, C-bit 0
I (7622) BT_L2CAP: L2CA_ConfigRsp()  CID: 0x0044  Result: 0 MTU present:0 Flush TO:0 FCR:0 FCS:0
D (7632) BT_L2CAP: L2CAP - st: CONFIG evt: 25
D (7632) BT_L2CAP: CID:0x0040 FCR Mode:0 Priority:2 TxDataRate:1 RxDataRate:1 Quota:20
I (7642) BT_L2CAP: L2CA_DataWrite()  CID: 0x0044  Len: 13
D (7652) BT_L2CAP: L2CAP - st: OPEN evt: 30
D (7732) BT_L2CAP: L2CAP - st: OPEN evt: 20
I (7732) BT_L2CAP: L2CA_DataWrite()  CID: 0x0044  Len: 19
D (7732) BT_L2CAP: L2CAP - st: OPEN evt: 30
D (7812) BT_L2CAP: L2CAP - st: OPEN evt: 20
I (7812) BT_L2CAP: L2CA_DataWrite()  CID: 0x0044  Len: 21
D (7812) BT_L2CAP: L2CAP - st: OPEN evt: 30
D (7892) BT_L2CAP: L2CAP - st: OPEN evt: 20
I (7892) BT_L2CAP: L2CA_DataWrite()  CID: 0x0044  Len: 21
D (7892) BT_L2CAP: L2CAP - st: OPEN evt: 30
D (7952) BT_L2CAP: L2CAP - st: OPEN evt: 20
I (7952) BT_L2CAP: L2CA_DataWrite()  CID: 0x0044  Len: 21
D (7952) BT_L2CAP: L2CAP - st: OPEN evt: 30
D (8012) BT_L2CAP: L2CAP - st: OPEN evt: 20
W (8012) BT_SDP: process_service_attr_rsp

I (8012) BT_L2CAP: L2CA_DisconnectReq()  CID: 0x0044
D (8022) BT_L2CAP: L2CAP - st: OPEN evt: 27
D (8032) BT_L2CAP: L2CAP - st: W4_L2CAP_DISC_RSP evt: 18
D (8032) BT_L2CAP: CID:0x0040 FCR Mode:0 Priority:2 TxDataRate:1 RxDataRate:1 Quota:20
I (8032) BT_L2CAP: L2CAP - Calling DisconnectCfm_Cb(), CID: 0x0044
D (8042) BT_APPL: bta_hh_sdp_cback: p_cb: 0x3ffc543c result 0x00,                             attr_mask 0x74, handle ff
D (8052) BT_APPL: bta_hh_tod_spt sub_class:0x4 supported
D (8062) BT_APPL: subclass = 0x 4
D (8062) BT_APPL: bta_hh_sm_execute: State 0x01 [BTA_HH_IDLE_ST], Event [BTA_HH_SDP_CMPL_EVT]

After failing both Wii remotes sit with their "connecting..." LEDs flashing, but they never time out (which is also what happens when they connect successfully, but you need to send a HID report to switch the LEDs off, and as the BT_HIDH open fails I never get access to the device to switch the LEDs off).

@boblane1
Copy link
Collaborator

Hi @benryves,

I am glad you have tried to find out the reason by yourself. The root reason is that the Bluetooth stack on ESP32 only supports one SDP procedure each time. In your case, the second HID connection is occurred while the first SDP procedure has not been finished. You can work around the issue by either staggering the two reconnection or adding the additional reconnection procedures when the previous reconnection is failed. If you choose the second solution, please apply the following patch first.

fix_hidh_connection_bug.zip

@benryves
Copy link
Author

Hi @boblane1,

Thank you very much for your advice and the patch. Unfortunately, this is all a bit beyond me - I find it extremely difficult to follow the Bluedroid code as a lot of it is indirect (e.g. via callback tables), not to mention the sheer volume of it, so I'm not really sure where I'd go to fix this. I've spent a few hours digging through the code but not really closer to a proper solution.

My workaround is to count the number of successfully connected and opened devices. If an incoming connection fails to open and there are no known successfully opened devices, I wait one second then deinit() and then re-init() all Bluetooth components. By doing this the devices that failed to open do get disconnected properly (and so you can try to reconnect them without having to pull their batteries out).

It's all a bit of a hack but I'm not really sure what the proper way to handle this is, but as far as user experience is concerned this at least masks the problem a bit better than before.

@boblane1
Copy link
Collaborator

Hi @benryves,

Maybe the deinit and re-init procedure is unnecessary. I think it's better to initiate the reconnection procedure directly, since it will not break the established connection. I will handle like the following comments.

void hidh_callback(void *handler_args, esp_event_base_t base, int32_t id, void *event_data)
{
...
    case ESP_HIDH_OPEN_EVENT: {
        if (param->open.status == ESP_OK) {
            const uint8_t *bda = esp_hidh_dev_bda_get(param->open.dev);
            ESP_LOGI(TAG, ESP_BD_ADDR_STR " OPEN: %s", ESP_BD_ADDR_HEX(bda), esp_hidh_dev_name_get(param->open.dev));
            esp_hidh_dev_dump(param->open.dev, stdout);
        } else {
            ESP_LOGE(TAG, " OPEN failed!");
            // push the bda to your own task work queue
        }
        break;
    }
...
}


your_own_app_task()
{
    // 1. fetch from the work queue and check if it is reconnection event
    // 2. delay some time
    // 3. call `esp_hidh_dev_open` to trigger the reconnection
}

@benryves
Copy link
Author

Hi @boblane1,

Thank you for the suggestion, that would certainly seem like the easiest answer.

How would you know the BDA of the device that failed to connect? param->open.dev is 0 when the connection fails, and attempting to use esp_hidh_dev_name_get to retrieve the BDA from 0 unsurprisingly results in a LoadProhibited Guru Meditation Error.

I'm not initiating the connection myself, the Wii remote is reconnecting automatically. I don't call esp_hidh_dev_open in this situation, I just handle hidh_callback with ESP_HIDH_OPEN_EVENT. Is there some callback I can subscribe to to see which devices have tried to connect, maybe?

@benryves
Copy link
Author

Hi @boblane1,

I've made some changes to a couple of files to copy the BDA to the ESP_HIDH_OPEN_EVENT's esp_hidh_event_data_t so that it can be recovered to trigger the reconnection: propagate_hidh_open_bdaddr.patch

If the ESP_HIDH_OPEN_EVENT fails and I then try to esp_hidh_dev_open using the queued BDA after a short delay it does "successfully" open the device - I get a successful status report from ESP_HIDH_OPEN_EVENT, esp_hidh_dev_dump prints out information about the connected device, and the user application assigns the controller to a controller slot. However, when it tries to send data to the controller I get a series of HID_ERR_NO_CONNECTION errors:

I (4227) BT: HIDH open 00:22:d7:6a:4b:bc: 
BDA:00:22:d7:6a:4b:bc, Status: OK, Connected: YES, Handle: 1, Usage: GAMEPAD
Name: , Manufacturer: , Serial Number:
PID: 0x0306, VID: 0x057e, VERSION: 0x0600
Report Map Length: 217
    VENDOR   INPUT REPORT, ID:  63, Length:  21
    VENDOR   INPUT REPORT, ID:  62, Length:  21
    VENDOR   INPUT REPORT, ID:  61, Length:  21
    VENDOR   INPUT REPORT, ID:  55, Length:  21
    VENDOR   INPUT REPORT, ID:  54, Length:  21
    VENDOR   INPUT REPORT, ID:  53, Length:  21
    VENDOR   INPUT REPORT, ID:  52, Length:  21
    VENDOR   INPUT REPORT, ID:  51, Length:  17
    VENDOR   INPUT REPORT, ID:  50, Length:  10
    VENDOR   INPUT REPORT, ID:  49, Length:   5
    VENDOR   INPUT REPORT, ID:  48, Length:   2
    VENDOR   INPUT REPORT, ID:  34, Length:   4
    VENDOR   INPUT REPORT, ID:  33, Length:  21
    VENDOR   INPUT REPORT, ID:  32, Length:   6
    VENDOR  OUTPUT REPORT, ID:  26, Length:   1
    VENDOR  OUTPUT REPORT, ID:  25, Length:   1
    VENDOR  OUTPUT REPORT, ID:  24, Length:  21
    VENDOR  OUTPUT REPORT, ID:  23, Length:   6
    VENDOR  OUTPUT REPORT, ID:  22, Length:  21
    VENDOR  OUTPUT REPORT, ID:  21, Length:   1
    VENDOR  OUTPUT REPORT, ID:  20, Length:   1
    VENDOR  OUTPUT REPORT, ID:  19, Length:   1
    VENDOR  OUTPUT REPORT, ID:  18, Length:   2
    VENDOR  OUTPUT REPORT, ID:  17, Length:   1
   GAMEPAD  OUTPUT REPORT, ID:  16, Length:   1
I (4277) MAIN: Running: 0:02, <NO VIDEO>
I (4347) MAIN: Assigning slot 0
I (4357) MAIN: Initialising player 0 Wii remote
E (4357) BT_HIDH: HID_ERR_NO_CONNECTION dev_handle 1
E (4367) BT_APPL: HID_HostWriteDev status:4
E (4417) BT_HIDH: HID_ERR_NO_CONNECTION dev_handle 1
E (4417) BT_APPL: HID_HostWriteDev status:4
E (4467) BT_HIDH: HID_ERR_NO_CONNECTION dev_handle 1
E (4467) BT_APPL: HID_HostWriteDev status:4
E (4517) BT_HIDH: HID_ERR_NO_CONNECTION dev_handle 1
E (4517) BT_APPL: HID_HostWriteDev status:4
E (4517) BT_HIDH: HID_ERR_NO_CONNECTION dev_handle 1
E (4517) BT_APPL: HID_HostWriteDev status:4
E (4567) BT_HIDH: HID_ERR_NO_CONNECTION dev_handle 1
E (4567) BT_APPL: HID_HostWriteDev status:4
E (4617) BT_HIDH: HID_ERR_NO_CONNECTION dev_handle 1
E (4617) BT_APPL: HID_HostWriteDev status:4
E (4667) BT_HIDH: HID_ERR_NO_CONNECTION dev_handle 1
E (4667) BT_APPL: HID_HostWriteDev status:4
E (4717) BT_HIDH: HID_ERR_NO_CONNECTION dev_handle 1
E (4717) BT_APPL: HID_HostWriteDev status:4
E (4767) BT_HIDH: HID_ERR_NO_CONNECTION dev_handle 1
E (4767) BT_APPL: HID_HostWriteDev status:4
I (5347) MAIN: Running: 0:03, <NO VIDEO>
I (6347) MAIN: Running: 0:04, <NO VIDEO>
I (7347) MAIN: Running: 0:05, <NO VIDEO>
I (8347) MAIN: Running: 0:06, <NO VIDEO>
I (9347) MAIN: Running: 0:07, <NO VIDEO>
I (10347) MAIN: Running: 0:08, <NO VIDEO>
I (11347) MAIN: Running: 0:09, <NO VIDEO>

If I then press some buttons on the controller I get similar error messages about the device not being found:

E (355597) BT_HIDH: Device Not Found: handle 0
E (355737) BT_HIDH: Device Not Found: handle 0
E (356047) BT_HIDH: Device Not Found: handle 0
E (356137) BT_HIDH: Device Not Found: handle 0
I (356347) MAIN: Running: 5:54, <NO VIDEO>
E (357237) BT_HIDH: Device Not Found: handle 0
I (357347) MAIN: Running: 5:55, <NO VIDEO>
E (357357) BT_HIDH: Device Not Found: handle 0

Similar to before, it's as if the controller is connected successfully but something is not properly associated internally.

I then tried applying your earlier patch, and this does change things but not for the better - this time after the reconnection attempt with the previously-received BDA I just get an ERR_SDP error, and the application goes into and endless loop of trying to reconnect and failing. I undid the changes from the patch and it goes back to an initial ERR_SDP followed by a "successful" opening that doesn't work (the BT_HIDH: Device Not Found: handle 0 errors mentioned above).


I spent some time digging through bt/host/bluedroid/stack/hid/hidh_api.c and it looks like HID_HostAddDev is called for the connecting device, then HID_HostRemoveDev after it fails to connect, followed by HID_HostAddDev after the failure to open the device. When I then re-open the device, HID_HostAddDev is not called again with the updated data. I changed HID_HostRemoveDev so that it immediately returns (and doesn't remove the device), which I know is obviously not the right thing to do, however as an experiment does actually work and allows the reopened device to be properly accessible from the user application.

Unfortunately, only one of the Wii remotes gets reopened. When two devices attempt to connect simultaneously both are registered (e.g. with HID_HostAddDev) however ERR_SDP in the ESP_HIDH_OPEN_EVENT is only reported for one of them and I don't receive any other notifications about attempted connections. As I only get one failure notification, the user application doesn't know it need to try to reopen two different BDAs.

At this point, I'm not sure what the best solution is, short of exposing more of the inner guts of hidh_api.c to the user application (e.g. the hh_cb.devices array) so it has a better idea of what connections have failed and what it can do to recover.


There is also one other solution, which is to crash and trigger a reset. By doing this the Wii remotes don't know they were intentionally disconnected (as they do from an deinit()/init() cycle) and so will automatically try to reconnect when the device comes back up instead of switching themselves off. This is a pretty awful solution, but certainly the easiest...

@boblane1
Copy link
Collaborator

boblane1 commented Jan 30, 2023

Hi @benryves,

When the HID connection procedure fails for SDP error, the stack doesn't destroy the L2CAP layer connection. Try the following patch again and reconnect, please let me know if the issue is solved, thanks!

fix_hidh_connection_bug_20230130.zip

@benryves
Copy link
Author

benryves commented Feb 3, 2023

Hi @boblane1,

Thank you very much for putting that together, unfortunately after applying those patches I still get stuck in an endless ERR_SDP loop whenever I try to reopen the device that failed to connect previously. I do get an error message about an invalid device handle of 255 (possibly set to -1 somewhere?) though, which I've not seen before...

W (5765) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
I (6255) MAIN: Running: 0:04, <NO VIDEO>
W (6775) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
E (6925) BT_BTM: tBTM_SEC_DEV:0x3ffd1b10 rs_disc_pending=0

W (7115) BT_SDP: process_service_attr_rsp

E (7175) BT_HIDH: OPEN ERROR: ERR_SDP
E (7175) BT: HIDH open failed (-1)
I (7175) BT: trying to reconnect
I (7175) BT: reconnecting 00:22:d7:6a:4b:bc...
W (7235) BT_HCI: hci cmd send: disconnect: hdl 0x80, rsn:0x13
W (7235) BT_APPL: bta_hh_co_close: dev_handle = 255, app_id = 0
W (7235) BT_APPL: bta_hh_co_close: Oops, dev_handle (255) is invalid...
W (7245) BT_APPL: bta_dm_act no entry for connected service cbs
E (7245) BT_BTC: Error: cannot find device with handle 255
E (7255) BT_HIDH: CLOSE ERROR: NO_CONNECTION
W (7255) BT_HCI: hcif disc complete: hdl 0x80, rsn 0x16
I (7265) BT: HIDH close 00:22:d7:6a:4b:bc: 
I (7265) MAIN: Running: 0:05, <NO VIDEO>
W (7435) BT_SDP: process_service_attr_rsp

I (8175) BT: re-opening 00:22:d7:6a:4b:bc
I (8275) MAIN: Running: 0:06, <NO VIDEO>
I (9275) MAIN: Running: 0:07, <NO VIDEO>
I (10275) MAIN: Running: 0:08, <NO VIDEO>
I (11275) MAIN: Running: 0:09, <NO VIDEO>
I (12275) MAIN: Running: 0:10, <NO VIDEO>
I (13275) MAIN: Running: 0:11, <NO VIDEO>
W (13285) BT_SDP: SDP - Rcvd conn cnf with error: 0x4  CID 0x43

W (13295) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4
E (13295) BT_HIDH: OPEN ERROR: ERR_SDP
E (13295) BT: HIDH open failed (-1)
I (13305) BT: trying to reconnect
I (13305) BT: reconnecting 00:22:d7:6a:4b:bc...
I (14275) MAIN: Running: 0:12, <NO VIDEO>
I (14305) BT: re-opening 00:22:d7:6a:4b:bc
I (15275) MAIN: Running: 0:13, <NO VIDEO>
I (16275) MAIN: Running: 0:14, <NO VIDEO>
I (17275) MAIN: Running: 0:15, <NO VIDEO>
I (18275) MAIN: Running: 0:16, <NO VIDEO>
I (19275) MAIN: Running: 0:17, <NO VIDEO>
W (19415) BT_SDP: SDP - Rcvd conn cnf with error: 0x4  CID 0x42

W (19415) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4
E (19415) BT_HIDH: OPEN ERROR: ERR_SDP
E (19415) BT: HIDH open failed (-1)
I (19425) BT: trying to reconnect
I (19425) BT: reconnecting 00:22:d7:6a:4b:bc...
I (20275) MAIN: Running: 0:18, <NO VIDEO>
I (20435) BT: re-opening 00:22:d7:6a:4b:bc
I (21275) MAIN: Running: 0:19, <NO VIDEO>
I (22275) MAIN: Running: 0:20, <NO VIDEO>
I (23275) MAIN: Running: 0:21, <NO VIDEO>
I (24275) MAIN: Running: 0:22, <NO VIDEO>
I (25275) MAIN: Running: 0:23, <NO VIDEO>
W (25555) BT_SDP: SDP - Rcvd conn cnf with error: 0x4  CID 0x43

W (25555) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4
E (25555) BT_HIDH: OPEN ERROR: ERR_SDP
E (25565) BT: HIDH open failed (-1)
I (25565) BT: trying to reconnect
I (25565) BT: reconnecting 00:22:d7:6a:4b:bc...
I (26275) MAIN: Running: 0:24, <NO VIDEO>
I (26575) BT: re-opening 00:22:d7:6a:4b:bc
I (27275) MAIN: Running: 0:25, <NO VIDEO>
I (28275) MAIN: Running: 0:26, <NO VIDEO>
I (29275) MAIN: Running: 0:27, <NO VIDEO>
I (30275) MAIN: Running: 0:28, <NO VIDEO>
I (31275) MAIN: Running: 0:29, <NO VIDEO>
W (31685) BT_SDP: SDP - Rcvd conn cnf with error: 0x4  CID 0x42

W (31685) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4
E (31685) BT_HIDH: OPEN ERROR: ERR_SDP
E (31695) BT: HIDH open failed (-1)
I (31695) BT: trying to reconnect
I (31695) BT: reconnecting 00:22:d7:6a:4b:bc...
I (32275) MAIN: Running: 0:30, <NO VIDEO>
I (32705) BT: re-opening 00:22:d7:6a:4b:bc
I (33275) MAIN: Running: 0:31, <NO VIDEO>
I (34275) MAIN: Running: 0:32, <NO VIDEO>
I (35275) MAIN: Running: 0:33, <NO VIDEO>
I (36275) MAIN: Running: 0:34, <NO VIDEO>
I (37275) MAIN: Running: 0:35, <NO VIDEO>
W (37825) BT_SDP: SDP - Rcvd conn cnf with error: 0x4  CID 0x43

W (37825) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4
E (37825) BT_HIDH: OPEN ERROR: ERR_SDP
E (37835) BT: HIDH open failed (-1)
I (37835) BT: trying to reconnect
I (37835) BT: reconnecting 00:22:d7:6a:4b:bc...
I (38275) MAIN: Running: 0:36, <NO VIDEO>
I (38845) BT: re-opening 00:22:d7:6a:4b:bc
I (39275) MAIN: Running: 0:37, <NO VIDEO>
I (40275) MAIN: Running: 0:38, <NO VIDEO>
I (41275) MAIN: Running: 0:39, <NO VIDEO>
I (42275) MAIN: Running: 0:40, <NO VIDEO>
I (43275) MAIN: Running: 0:41, <NO VIDEO>
W (43955) BT_SDP: SDP - Rcvd conn cnf with error: 0x4  CID 0x42

W (43955) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4
E (43955) BT_HIDH: OPEN ERROR: ERR_SDP
E (43965) BT: HIDH open failed (-1)
I (43965) BT: trying to reconnect
I (43965) BT: reconnecting 00:22:d7:6a:4b:bc...
I (44275) MAIN: Running: 0:42, <NO VIDEO>
I (44975) BT: re-opening 00:22:d7:6a:4b:bc

(In this case the "trying to reconnect" message appears when the connection fails, "reconnecting 00:22:d7:6a:4b:bc..." appears when the pending connection is successfully queued for later retrieval by a task, "re-opening 00:22:d7:6a:4b:bc" appears in the reconnection task when esp_hidh_dev_open returns successfully).

@boblane1
Copy link
Collaborator

boblane1 commented Feb 6, 2023

Hi @benryves,

In the previous patch, when the open operation failed, it comes with both ESP_HIDH_OPEN_EVENT and ESP_HIDH_CLOSE_EVENT events. Please initiate the reconnect operation in the ESP_HIDH_CLOSE_EVENT event which is cased by open failure or just delay some time to recover the stack. Please try again to see if the issue persists.

@benryves
Copy link
Author

benryves commented Feb 6, 2023

Hi @boblane1

Thanks for the feedback, previously I was only using the patch you supplied in fix_hidh_connection_bug_20230130.zip, I reset to a clean version of 5.0 and then applied fix_hidh_connection_bug.zip and then the later patch. After applying both patches I now see the HIDH_CLOSE event for the first (failed) connection attempt, but subsequent failures don't appear to trigger this event.

When the HIDH_OPEN event fails I store the BDA in a queue and start a task that waits for one second, then pulls items from the queue and tries to reopen them with a one second delay between them. I've made my logging a bit clearer to show that it's queueing up connection attempts (rather than immediately reopening the connection) as well as extended the initial delay to three seconds. (As I only get the HIDH_CLOSE event for the first failed attempt I suppose handling this event instead of a failed HIDH_OPEN would prevent my code from going into an infinite loop, it would only retry once).

W (1921) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
W (2881) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
E (3071) BT_BTM: tBTM_SEC_DEV:0x3ffd297c rs_disc_pending=0

W (3241) BT_SDP: process_service_attr_rsp

E (3271) BT_HIDH: OPEN ERROR: ERR_SDP
E (3281) BT: HIDH open failed (-1)
I (3281) BT: will try to reconnect
I (3281) BT: queued 00:21:bd:07:b6:41 for reconnection...
W (3301) BT_HCI: hci cmd send: disconnect: hdl 0x80, rsn:0x13
W (3301) BT_APPL: bta_hh_co_close: dev_handle = 255, app_id = 0
W (3301) BT_APPL: bta_hh_co_close: Oops, dev_handle (255) is invalid...
W (3311) BT_APPL: bta_dm_act no entry for connected service cbs
E (3311) BT_BTC: Error: cannot find device with handle 255
E (3321) BT_HIDH: CLOSE ERROR: NO_CONNECTION
I (3321) BT: HIDH close 00:21:bd:07:b6:41: 
W (3331) BT_HCI: hcif disc complete: hdl 0x80, rsn 0x16
W (3621) BT_SDP: process_service_attr_rsp

I (3911) MAIN: Running: 0:00, <NO VIDEO>
I (4911) MAIN: Running: 0:01, <NO VIDEO>
I (5911) MAIN: Running: 0:02, <NO VIDEO>
I (6281) BT: re-opening 00:21:bd:07:b6:41
I (6911) MAIN: Running: 0:03, <NO VIDEO>
I (7911) MAIN: Running: 0:04, <NO VIDEO>
I (8911) MAIN: Running: 0:05, <NO VIDEO>
I (9911) MAIN: Running: 0:06, <NO VIDEO>
I (10911) MAIN: Running: 0:07, <NO VIDEO>
W (11391) BT_SDP: SDP - Rcvd conn cnf with error: 0x4  CID 0x42

W (11391) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4
E (11391) BT_HIDH: OPEN ERROR: ERR_SDP
E (11391) BT: HIDH open failed (-1)
I (11401) BT: will try to reconnect
I (11401) BT: queued 00:21:bd:07:b6:41 for reconnection...
I (11911) MAIN: Running: 0:08, <NO VIDEO>
I (12911) MAIN: Running: 0:09, <NO VIDEO>
I (13911) MAIN: Running: 0:10, <NO VIDEO>
I (14411) BT: re-opening 00:21:bd:07:b6:41
I (14911) MAIN: Running: 0:11, <NO VIDEO>
I (15911) MAIN: Running: 0:12, <NO VIDEO>
I (16911) MAIN: Running: 0:13, <NO VIDEO>
I (17911) MAIN: Running: 0:14, <NO VIDEO>
I (18911) MAIN: Running: 0:15, <NO VIDEO>
W (19521) BT_SDP: SDP - Rcvd conn cnf with error: 0x4  CID 0x43

W (19521) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4
E (19531) BT_HIDH: OPEN ERROR: ERR_SDP
E (19531) BT: HIDH open failed (-1)
I (19531) BT: will try to reconnect
I (19541) BT: queued 00:21:bd:07:b6:41 for reconnection...
I (19911) MAIN: Running: 0:16, <NO VIDEO>
I (20911) MAIN: Running: 0:17, <NO VIDEO>
I (21911) MAIN: Running: 0:18, <NO VIDEO>
I (22541) BT: re-opening 00:21:bd:07:b6:41
I (22911) MAIN: Running: 0:19, <NO VIDEO>
I (23911) MAIN: Running: 0:20, <NO VIDEO>
I (24911) MAIN: Running: 0:21, <NO VIDEO>
I (25911) MAIN: Running: 0:22, <NO VIDEO>
I (26911) MAIN: Running: 0:23, <NO VIDEO>
W (27651) BT_SDP: SDP - Rcvd conn cnf with error: 0x4  CID 0x42

W (27651) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4
E (27651) BT_HIDH: OPEN ERROR: ERR_SDP
E (27651) BT: HIDH open failed (-1)
I (27661) BT: will try to reconnect
I (27661) BT: queued 00:21:bd:07:b6:41 for reconnection...
I (27911) MAIN: Running: 0:24, <NO VIDEO>
I (28911) MAIN: Running: 0:25, <NO VIDEO>

Would it be useful if I was to try to put together the smallest program I can that demonstrates the issue? (You'd need at least two Wii remotes and a push button to perform the initial sync, then once they're paired you could reset the ESP32 until they both tried to reconnect at the same time and triggered the issue).

@boblane1
Copy link
Collaborator

boblane1 commented Feb 6, 2023

Hi @benryves,

W (11391) BT_SDP: SDP - Rcvd conn cnf with error: 0x4 CID 0x42

W (11391) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4

st 0x4 means the SDP connection is timeout. It seems that the Wii can not response the reconnection of ESP32(HID Host) when the previous connection is failed.

@benryves
Copy link
Author

benryves commented Feb 6, 2023

Thank you for the confirmation, @boblane1!

My previous solution was to de-init and re-init the Bluetooth stack on error, this cleanly disconnects the Wii remotes and allows them to be reconnected by pressing a button on them to wake them up (when they encounter an error otherwise they get stuck in an unresponsive state unless you hold the power button down or pull a battery out). I think I may stick to that solution, as it's the least confusing for the user.

@espressif-bot espressif-bot added Resolution: NA Issue resolution is unavailable Status: Done Issue is done internally Resolution: Done Issue is done internally and removed Status: Opened Issue is new Resolution: NA Issue resolution is unavailable labels Mar 9, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Resolution: Done Issue is done internally Status: Done Issue is done internally Type: Bug bugs in IDF
Projects
None yet
Development

No branches or pull requests

3 participants